Skip to content

Debug decode cache #2

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 5 commits into
base: nlp/cache-start-pos
Choose a base branch
from
Open

Debug decode cache #2

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
5b3eff1
Add encoded size to start_pos
Jan 16, 2025
722fb78
Only in chat mode
Jan 16, 2025
f8f7ad2
Debug logs
Jan 17, 2025
ba5d527
debug
Jan 23, 2025
44d9a07
fix
Jan 23, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
121 changes: 68 additions & 53 deletions torchchat/generate.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
from pathlib import Path
from typing import Any, Dict, List, Optional, Sequence, Tuple, Union

import pydevd_pycharm
import torch
import torch._dynamo.config
import torch._inductor.config
Expand Down Expand Up @@ -575,7 +576,10 @@ def decode_n_tokens(
batch=batch,
**sampling_kwargs,
)
input_pos += 1
if os.getenv('DEBUG_CACHE'):
print(f"last cur_token: {cur_token}")
print(f"final token {final_token} input_pos: {input_pos}")
yield cur_token.clone(), next_prob.clone()
break

if not encountered_eos:
Expand Down Expand Up @@ -836,7 +840,8 @@ def _callback(self, x, *, buffer, done_generating):
done_generating = True
buffer = buffer[:-1] # drop the eot_id from the output buffer
if len(buffer) == 4 or done_generating:
print("".join(buffer), end="", flush=True)
if not os.getenv('DEBUG_CACHE'):
print("".join(buffer), end="", flush=True)
buffer.clear()

def _gen_model_input(
Expand Down Expand Up @@ -1174,6 +1179,7 @@ def callback(x, *, done_generating=False):
prof = torch.profiler.profile()
t0 = time.perf_counter()
num_tokens_generated = 0
local_token_tensor = []
with prof:
generator_func = self.generate(
self.model,
Expand All @@ -1192,8 +1198,13 @@ def callback(x, *, done_generating=False):
max_seq_length=max_seq_length,
attention_backend=self.builder_args.attention_backend,
)
if generator_args.chat_mode:
start_pos += encoded.size(0)
for token_tensor, metrics in generator_func:
if token_tensor is not None:
if os.getenv('DEBUG_CACHE'):
# print(f"Token tensor: {token_tensor}")
local_token_tensor.append(token_tensor.tolist()[0])
start_pos += token_tensor.size(0)
num_tokens_generated += token_tensor.size(0)
if metrics is not None:
Expand All @@ -1202,59 +1213,63 @@ def callback(x, *, done_generating=False):
jit_compile = is_first_sample and (
generator_args.compile or generator_args.compile_prefill
)
if os.getenv('DEBUG_CACHE'):
print(f"local_token_tensor: {local_token_tensor}")
print(self.tokenizer.decode(local_token_tensor))
compilation_time = time.perf_counter() - t0
device_sync(device=self.builder_args.device)
t = time.perf_counter() - t0
if hasattr(prof, "export_chrome_trace"):
if self.builder_args.device == "cpu":
print(prof.key_averages().table(sort_by="self_cpu_time_total"))
elif self.builder_args.device == "cuda":
print(prof.key_averages().table(sort_by="self_cuda_time_total"))
else:
print(prof.key_averages().table(sort_by="self_xpu_time_total"))
prof.export_chrome_trace(f"{self.profile}.json")

if start_pos >= max_seq_length:
print(
f"[Max Sequence Length {max_seq_length} Reached. Ending Conversation.]"
)
print("---------------------------------------------------")

tokens_sec = (num_tokens_generated + 1) / t
first_token_sec = 1 / aggregate_metrics.get("time_to_first_token", 0)
next_tokens_sec = num_tokens_generated / (
t - aggregate_metrics.get("time_to_first_token", 0)
)

if jit_compile:
print(
f"just-in-time compilation time (incl run time): {compilation_time:.2} seconds"
)
else:
# aggregate_metrics will not append when is jit_compile, which will affect the average numbers.
aggregate_metrics["tokens_per_sec"].append(tokens_sec)
aggregate_metrics["first_token_per_sec"].append(first_token_sec)
aggregate_metrics["next_tokens_per_sec"].append(next_tokens_sec)

logging.info(
f"\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\
\nGenerated {num_tokens_generated} tokens \
\nTime for inference {i + 1}: {t:.04f} sec total \
\nTime to first token: {aggregate_metrics.get('time_to_first_token', 0):.04f} sec \
with {'sequential' if generator_args.sequential_prefill else 'parallel'} prefill.\
\n\n Total throughput: {tokens_sec:.04f} tokens/sec, {1 / tokens_sec:.04f} s/token \
\nFirst token throughput: {first_token_sec:.04f} tokens/sec, {1 / first_token_sec:.04f} s/token \
\n Next token throughput: {next_tokens_sec:.04f} tokens/sec, {1 / next_tokens_sec:.04f} s/token \
"
)
logging.info(
f"\nBandwidth achieved: {model_size * tokens_sec / 1e9:.02f} GB/s"
)
if i == 0:
logging.info(
f"*** This first iteration will include cold start effects for dynamic import, hardware caches{', JIT compilation' if jit_compile else ''}. ***"
)
print("\n========================================\n")
# t = time.perf_counter() - t0
# if hasattr(prof, "export_chrome_trace"):
# if self.builder_args.device == "cpu":
# print(prof.key_averages().table(sort_by="self_cpu_time_total"))
# elif self.builder_args.device == "cuda":
# print(prof.key_averages().table(sort_by="self_cuda_time_total"))
# else:
# print(prof.key_averages().table(sort_by="self_xpu_time_total"))
# prof.export_chrome_trace(f"{self.profile}.json")
#
# if start_pos >= max_seq_length:
# print(
# f"[Max Sequence Length {max_seq_length} Reached. Ending Conversation.]"
# )
# print("---------------------------------------------------")
#
# tokens_sec = (num_tokens_generated + 1) / t
# first_token_sec = 1 / aggregate_metrics.get("time_to_first_token", 0)
# next_tokens_sec = num_tokens_generated / (
# t - aggregate_metrics.get("time_to_first_token", 0)
# )
#
# if jit_compile:
# print(
# f"just-in-time compilation time (incl run time): {compilation_time:.2} seconds"
# )
# else:
# # aggregate_metrics will not append when is jit_compile, which will affect the average numbers.
# aggregate_metrics["tokens_per_sec"].append(tokens_sec)
# aggregate_metrics["first_token_per_sec"].append(first_token_sec)
# aggregate_metrics["next_tokens_per_sec"].append(next_tokens_sec)
#
# logging.info(
# f"\n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\
# \nGenerated {num_tokens_generated} tokens \
# \nTime for inference {i + 1}: {t:.04f} sec total \
# \nTime to first token: {aggregate_metrics.get('time_to_first_token', 0):.04f} sec \
# with {'sequential' if generator_args.sequential_prefill else 'parallel'} prefill.\
# \n\n Total throughput: {tokens_sec:.04f} tokens/sec, {1 / tokens_sec:.04f} s/token \
# \nFirst token throughput: {first_token_sec:.04f} tokens/sec, {1 / first_token_sec:.04f} s/token \
# \n Next token throughput: {next_tokens_sec:.04f} tokens/sec, {1 / next_tokens_sec:.04f} s/token \
# "
# )
# logging.info(
# f"\nBandwidth achieved: {model_size * tokens_sec / 1e9:.02f} GB/s"
# )
# if i == 0:
# logging.info(
# f"*** This first iteration will include cold start effects for dynamic import, hardware caches{', JIT compilation' if jit_compile else ''}. ***"
# )
# print("\n========================================\n")
print()
if start_pos >= max_seq_length:
if generator_args.chat_mode:
break
Expand Down
11 changes: 11 additions & 0 deletions torchchat/model.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -723,6 +723,11 @@ def distribute(self, device_mesh: DeviceMesh):

def forward(self, x: Tensor, input_pos: Optional[Tensor] = None, cache_lane: int = 0) -> Tensor:
assert self.freqs_cis is not None, "Caches must be initialized first"
if os.getenv('DEBUG_CACHE'):
def get_cache_sample(input_pos):
return self.layers['0'].attention.kv_cache[0].k_cache[0][0][input_pos][0].tolist()
first_pos = input_pos[0].item()
print(f"Transformer before forward input pos: {input_pos}; (pos={first_pos} cache_sample={get_cache_sample(first_pos)})" , end=" | ")
mask = self.causal_mask[None, None, input_pos]
freqs_cis = self.freqs_cis[input_pos]
if self.tok_embeddings:
Expand All @@ -743,6 +748,12 @@ def forward(self, x: Tensor, input_pos: Optional[Tensor] = None, cache_lane: int
if self.config.logits_scaling:
x = x / self.config.logits_scaling
# print(f"output shape: {x.shape}")
if os.getenv('DEBUG_CACHE'):
def get_cache_sample(input_pos):
return self.layers['0'].attention.kv_cache[0].k_cache[0][0][input_pos][0].tolist()
first_pos = input_pos[0].item()
print(f"Transformer after forward cache (pos={first_pos}; cache_sample={get_cache_sample(first_pos)})")

return x


Expand Down
Loading