[RX] 2026-09-21T23:09:54.768+08:00 [2026-09-21 23:09:50][LAT_TEST] === CH395F Phase 13 Tests (chip+queue latency, L3~L7/L10) ===
[RX] 2026-09-21T23:09:54.768+08:00 [2026-09-21 23:09:50][LAT_TEST] [LAT] run_id=2910 phase=13 cal core_clk=168000000 us_per_1024cyc=6
[RX] 2026-09-21T23:09:54.779+08:00 [2026-09-21 23:09:50][LAT_TEST] [LAT] waiting for peer HELLO (port 8080, latency_peer.py --mode net)
[RX] 2026-09-21T23:09:56.973+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=4
[RX] 2026-09-21T23:09:56.973+08:00 [2026-09-21 23:09:53][LAT_TEST] [LAT] peer session start
[RX] 2026-09-21T23:09:56.994+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.046+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.088+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.140+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.193+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.245+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.287+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.340+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.393+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.447+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.510+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.552+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.593+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.645+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.698+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.739+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.792+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.854+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.906+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.948+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.959+08:00 [2026-09-21 23:09:53][LAT_TEST] [LAT] seg=queue_rt_recv n=20 min=5513 med=5997 p95=6033 max=6033 us spikes=0
[RX] 2026-09-21T23:09:57.969+08:00 [2026-09-21 23:09:53][LAT_TEST] [LAT] verdict=OK seg=queue_rt_recv (med=5997ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:09:58.012+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=queue_rt_send n=20 min=838 med=987 p95=1209 max=1209 us spikes=0
[RX] 2026-09-21T23:09:58.022+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=queue_rt_send (med=987ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:09:58.169+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=chunk_wait n=64 min=214 med=219 p95=238 max=381 us spikes=0
[RX] 2026-09-21T23:09:58.179+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=chunk_wait (med=219ms warn<=10000 crit<=500000 spikes=0/0)
[RX] 2026-09-21T23:09:58.243+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=logtax_line n=10 min=4394 med=4396 p95=4422 max=4422 us spikes=0
[RX] 2026-09-21T23:09:58.253+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=logtax_line (med=4396ms warn<=10000 crit<=25000 spikes=0/0)
[RX] 2026-09-21T23:09:58.285+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.338+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.400+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.462+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.525+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.587+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.640+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.692+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.744+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.806+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.806+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=req2first_mcu n=10 min=308 med=319 p95=338 max=338 us spikes=0
[RX] 2026-09-21T23:09:58.817+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=req2first_mcu (med=319ms warn<=20000 crit<=200000 spikes=0/0)
[RX] 2026-09-21T23:09:58.859+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:58.922+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:58.975+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.038+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.090+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.152+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.204+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.266+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.319+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.392+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.402+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] seg=fullframe_mcu n=10 min=5991 med=6028 p95=6066 max=6066 us spikes=0
[RX] 2026-09-21T23:09:59.412+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] verdict=OK seg=fullframe_mcu (med=6028ms warn<=50000 crit<=500000 spikes=0/0)
[RX] 2026-09-21T23:09:59.444+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] summary verdict=OK
[RX] 2026-09-21T23:09:59.454+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] report complete
[RX] 2026-09-21T23:09:59.454+08:00 [2026-09-21 23:09:55][LAT_TEST] === Phase 13: 1/1 PASSED (failed=0) ===
[RX] 2026-09-21T23:09:59.475+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] note: CLOSED on abort -> re-listen via chip
[RX] 2026-09-21T23:10:00.068+08:00 [2026-09-21 23:09:56][NET] sock2 auto-relisten ok
