|
| 1 | +"""Analyze server logs to extract token count information. |
| 2 | +
|
| 3 | +Usage: |
| 4 | + # Analyze from stdin |
| 5 | + cat server.log | python analyze_server_log.py |
| 6 | +
|
| 7 | + # Or analyze from file |
| 8 | + python analyze_server_log.py server.log |
| 9 | +""" |
| 10 | + |
| 11 | +import re |
| 12 | +import sys |
| 13 | +from collections import defaultdict |
| 14 | + |
| 15 | + |
| 16 | +def parse_prefill_line(line): |
| 17 | + """Parse prefill batch log line.""" |
| 18 | + # Example: Prefill batch. #new-seq: 8, #new-token: 65536, #cached-token: 0, token usage: 0.21, #running-req: 8, #queue-req: 8, |
| 19 | + match = re.search( |
| 20 | + r"#new-seq:\s*(\d+).*#new-token:\s*(\d+).*#cached-token:\s*(\d+).*token usage:\s*([\d.]+).*#running-req:\s*(\d+).*#queue-req:\s*(\d+)", |
| 21 | + line, |
| 22 | + ) |
| 23 | + if match: |
| 24 | + return { |
| 25 | + "type": "prefill", |
| 26 | + "new_seq": int(match.group(1)), |
| 27 | + "new_token": int(match.group(2)), |
| 28 | + "cached_token": int(match.group(3)), |
| 29 | + "token_usage": float(match.group(4)), |
| 30 | + "running_req": int(match.group(5)), |
| 31 | + "queue_req": int(match.group(6)), |
| 32 | + } |
| 33 | + return None |
| 34 | + |
| 35 | + |
| 36 | +def parse_decode_line(line): |
| 37 | + """Parse decode batch log line.""" |
| 38 | + # Example: Decode batch. #running-req: 8, #token: 286848, token usage: 0.96, gen throughput (token/s): 232.27, #queue-req: 0, |
| 39 | + match = re.search( |
| 40 | + r"#running-req:\s*(\d+).*#token:\s*(\d+).*token usage:\s*([\d.]+).*gen throughput.*:\s*([\d.]+).*#queue-req:\s*(\d+)", |
| 41 | + line, |
| 42 | + ) |
| 43 | + if match: |
| 44 | + return { |
| 45 | + "type": "decode", |
| 46 | + "running_req": int(match.group(1)), |
| 47 | + "token": int(match.group(2)), |
| 48 | + "token_usage": float(match.group(3)), |
| 49 | + "gen_throughput": float(match.group(4)), |
| 50 | + "queue_req": int(match.group(5)), |
| 51 | + } |
| 52 | + return None |
| 53 | + |
| 54 | + |
| 55 | +def main(): |
| 56 | + if len(sys.argv) > 1: |
| 57 | + # Read from file |
| 58 | + with open(sys.argv[1], "r") as f: |
| 59 | + lines = f.readlines() |
| 60 | + else: |
| 61 | + # Read from stdin |
| 62 | + lines = sys.stdin.readlines() |
| 63 | + |
| 64 | + print("=" * 80) |
| 65 | + print("SERVER LOG ANALYSIS") |
| 66 | + print("=" * 80) |
| 67 | + |
| 68 | + prefill_logs = [] |
| 69 | + decode_logs = [] |
| 70 | + |
| 71 | + for line in lines: |
| 72 | + if "Prefill batch" in line: |
| 73 | + data = parse_prefill_line(line) |
| 74 | + if data: |
| 75 | + prefill_logs.append(data) |
| 76 | + elif "Decode batch" in line: |
| 77 | + data = parse_decode_line(line) |
| 78 | + if data: |
| 79 | + decode_logs.append(data) |
| 80 | + |
| 81 | + # Analyze prefill logs |
| 82 | + if prefill_logs: |
| 83 | + print(f"\nPREFILL BATCHES: {len(prefill_logs)} found") |
| 84 | + print("-" * 80) |
| 85 | + print( |
| 86 | + f"{'#':>4} {'NewSeq':>8} {'NewTok':>10} {'CacheTok':>10} {'Usage':>8} {'RunReq':>8} {'QueueReq':>10}" |
| 87 | + ) |
| 88 | + print("-" * 80) |
| 89 | + |
| 90 | + total_new_tokens = 0 |
| 91 | + for i, log in enumerate(prefill_logs[:20]): # Show first 20 |
| 92 | + print( |
| 93 | + f"{i+1:4d} {log['new_seq']:8d} {log['new_token']:10d} {log['cached_token']:10d} " |
| 94 | + f"{log['token_usage']:8.2f} {log['running_req']:8d} {log['queue_req']:10d}" |
| 95 | + ) |
| 96 | + total_new_tokens += log["new_token"] |
| 97 | + |
| 98 | + if len(prefill_logs) > 20: |
| 99 | + print(f"... and {len(prefill_logs) - 20} more") |
| 100 | + |
| 101 | + print(f"\nPrefill Statistics:") |
| 102 | + print(f" Total new tokens across all prefills: {total_new_tokens:,}") |
| 103 | + print(f" Average tokens per prefill: {total_new_tokens / len(prefill_logs):,.0f}") |
| 104 | + if prefill_logs: |
| 105 | + print(f" First prefill new tokens: {prefill_logs[0]['new_token']:,}") |
| 106 | + |
| 107 | + # Analyze decode logs |
| 108 | + if decode_logs: |
| 109 | + print(f"\n{'=' * 80}") |
| 110 | + print(f"DECODE BATCHES: {len(decode_logs)} found") |
| 111 | + print("-" * 80) |
| 112 | + print( |
| 113 | + f"{'#':>4} {'RunReq':>8} {'#Token':>12} {'Usage':>8} {'Throughput':>12} {'QueueReq':>10}" |
| 114 | + ) |
| 115 | + print("-" * 80) |
| 116 | + |
| 117 | + for i, log in enumerate(decode_logs[:20]): # Show first 20 |
| 118 | + print( |
| 119 | + f"{i+1:4d} {log['running_req']:8d} {log['token']:12,d} {log['token_usage']:8.2f} " |
| 120 | + f"{log['gen_throughput']:12.2f} {log['queue_req']:10d}" |
| 121 | + ) |
| 122 | + |
| 123 | + if len(decode_logs) > 20: |
| 124 | + print(f"... and {len(decode_logs) - 20} more") |
| 125 | + |
| 126 | + print(f"\nDecode Statistics:") |
| 127 | + tokens_by_running_req = defaultdict(list) |
| 128 | + for log in decode_logs: |
| 129 | + tokens_by_running_req[log["running_req"]].append(log["token"]) |
| 130 | + |
| 131 | + for running_req in sorted(tokens_by_running_req.keys()): |
| 132 | + tokens = tokens_by_running_req[running_req] |
| 133 | + avg_token = sum(tokens) / len(tokens) |
| 134 | + min_token = min(tokens) |
| 135 | + max_token = max(tokens) |
| 136 | + print( |
| 137 | + f" Running {running_req:2d} requests: avg={avg_token:10.0f}, min={min_token:10,d}, max={max_token:10,d} tokens ({len(tokens)} samples)" |
| 138 | + ) |
| 139 | + if running_req > 0: |
| 140 | + avg_per_req = avg_token / running_req |
| 141 | + print(f" → Avg per request: {avg_per_req:,.0f} tokens") |
| 142 | + |
| 143 | + # Key findings |
| 144 | + print(f"\n{'=' * 80}") |
| 145 | + print("KEY FINDINGS") |
| 146 | + print("=" * 80) |
| 147 | + |
| 148 | + if prefill_logs and decode_logs: |
| 149 | + first_prefill_tokens = prefill_logs[0]["new_token"] |
| 150 | + first_decode_tokens = decode_logs[0]["token"] if decode_logs else 0 |
| 151 | + |
| 152 | + print(f"\n1. First prefill batch:") |
| 153 | + print(f" New tokens: {first_prefill_tokens:,}") |
| 154 | + print(f" New sequences: {prefill_logs[0]['new_seq']}") |
| 155 | + print(f" Average per sequence: {first_prefill_tokens / prefill_logs[0]['new_seq']:,.0f}") |
| 156 | + |
| 157 | + print(f"\n2. Decode batch token count:") |
| 158 | + print(f" Token count: {first_decode_tokens:,}") |
| 159 | + print(f" Running requests: {decode_logs[0]['running_req']}") |
| 160 | + if decode_logs[0]["running_req"] > 0: |
| 161 | + print( |
| 162 | + f" Average per request: {first_decode_tokens / decode_logs[0]['running_req']:,.0f}" |
| 163 | + ) |
| 164 | + |
| 165 | + print( |
| 166 | + f"\n3. Ratio (decode/prefill): {first_decode_tokens / first_prefill_tokens if first_prefill_tokens > 0 else 0:.2f}x" |
| 167 | + ) |
| 168 | + |
| 169 | + print("\n" + "=" * 80) |
| 170 | + |
| 171 | + |
| 172 | +if __name__ == "__main__": |
| 173 | + main() |
0 commit comments