AI语音为什么反应慢？给采音、上传、首字和播放分段计时

python tools/verify_project.py
python tools/project.py configure
python tools/project.py build
python tools/project.py manifest

python tools/project.py flash --port YOUR_UART_BRIDGE_PORT
python tools/project.py monitor --port YOUR_UART_BRIDGE_PORT

python -m pip install -r python-requirements.lock
python tools/capture_trace.py --port YOUR_UART_BRIDGE_PORT --baud 115200 --seconds 1200 --output trace-private.txt
python tools/analyze_trace.py trace-private.txt --origin serial-unverified --attempts attempts.csv --min-complete 20 --output local-report.json

python tests/run_trace_host.py --output /tmp/a09-recorder-contract
python tests/check_files_pty.py --producer-dir /tmp/a09-recorder-contract --output /tmp/a09-file-pty-contract
python tests/check_transport_metadata.py --output /tmp/a09-wire-contract
python tests/check_project_tool.py --output /tmp/a09-project-tool-contract

// ---- firmware/main/lab_latency_policy.h ----
// SPDX-License-Identifier: MIT
#pragma once
#include <array>
#include <cstddef>
#include <cstdint>
#include <limits>
#include <mutex>
namespace a09 {
enum class Event : uint8_t {
    BEGIN,
    LISTEN_CMD_RETURN,
    MIC_CHUNK_RETURN,
    FIRST_SEND_RETURN,
    STOP_LISTEN_RETURN,
    STT_JSON,
    TTS_START_JSON,
    FIRST_TTS_SENTENCE_JSON,
    FIRST_TTS_AUDIO_CALLBACK,
    FIRST_PCM_WRITE_ENTER,
    FIRST_PCM_WRITE_RETURN,
    NETWORK_FAILURE,
    SEND_FAILURE,
    DECODE_QUEUE_REJECT,
    TIMEOUT,
    REENTRY,
    CLOCK_INVALID,
    END,
    COUNT
};
inline const char* name(Event e) {
    constexpr const char* names[] = {"BEGIN",
                                     "LISTEN_CMD_RETURN",
                                     "MIC_CHUNK_RETURN",
                                     "FIRST_SEND_RETURN",
                                     "STOP_LISTEN_RETURN",
                                     "STT_JSON",
                                     "TTS_START_JSON",
                                     "FIRST_TTS_SENTENCE_JSON",
                                     "FIRST_TTS_AUDIO_CALLBACK",
                                     "FIRST_PCM_WRITE_ENTER",
                                     "FIRST_PCM_WRITE_RETURN",
                                     "NETWORK_FAILURE",
                                     "SEND_FAILURE",
                                     "DECODE_QUEUE_REJECT",
                                     "TIMEOUT",
                                     "REENTRY",
                                     "CLOCK_INVALID",
                                     "END"};
    return e < Event::COUNT ? names[static_cast<unsigned>(e)] : "INVALID";
}
struct Row {
    uint64_t seq = 0, turn = 0, us = 0;
    Event event = Event::BEGIN;
    int32_t detail = 0;
};
struct Report {
    std::array<Row, 20> rows{};
    std::size_t count = 0;
    bool overflow = false;
};
// No I/O/allocation while locked. Only a completed report may be taken/flushed.
// Does not change the upstream conversation, audio, or network state.
class Recorder {
public:
    uint64_t begin(uint64_t now) {
        std::lock_guard<std::mutex> lock(mutex_);
        if (active_) {
            terminal(Event::REENTRY, now);
            return 0;
        }
        if (ready_ || turn_ == std::numeric_limits<uint64_t>::max())
            return 0;
        ++turn_;
        start_ = now;
        mask_ = 0;
        count_ = 0;
        overflow_ = false;
        active_ = true;
        put(Event::BEGIN, now, 0);
        return turn_;
    }
    uint64_t epoch() {
        std::lock_guard<std::mutex> lock(mutex_);
        return active_ ? turn_ : 0;
    }
    bool mark(uint64_t epoch, Event event, uint64_t now, int32_t detail = 0) {
        std::lock_guard<std::mutex> lock(mutex_);
        if (!active_ || !epoch || epoch != turn_ || event >= Event::COUNT ||
            event == Event::BEGIN || event == Event::END)
            return false;
        if (now < start_) {
            terminal(Event::CLOCK_INVALID, start_);
            return false;
        }
        const auto bit = uint32_t(1) << static_cast<unsigned>(event);
        if (mask_ & bit)
            return false;
        put(event, now, detail);
        if (event == Event::FIRST_PCM_WRITE_RETURN)
            finish(now, 0);
        return true;
    }
    void fail_epoch(uint64_t epoch, Event reason, uint64_t now) {
        std::lock_guard<std::mutex> lock(mutex_);
        if (active_ && epoch && epoch == turn_)
            terminal(now < start_ ? Event::CLOCK_INVALID : reason, now < start_ ? start_ : now);
    }
    void fail(Event reason, uint64_t now) {
        std::lock_guard<std::mutex> lock(mutex_);
        if (active_)
            terminal(now < start_ ? Event::CLOCK_INVALID : reason, now < start_ ? start_ : now);
    }
    void poll(uint64_t now) {
        std::lock_guard<std::mutex> lock(mutex_);
        if (active_ && now < start_)
            terminal(Event::CLOCK_INVALID, start_);
        else if (active_ && now - start_ >= 60000000ULL)
            terminal(Event::TIMEOUT, now);
    }
    bool take(Report& out) {
        std::lock_guard<std::mutex> lock(mutex_);
        if (!ready_)
            return false;
        out.rows = rows_;
        out.count = count_;
        out.overflow = overflow_;
        ready_ = false;
        count_ = 0;
        return true;
    }

private:
    void put(Event e, uint64_t now, int32_t detail) {
        if (count_ == rows_.size()) {
            overflow_ = true;
            active_ = false;
            ready_ = true;
            return;
        }
        rows_[count_++] = {++sequence_, turn_, now, e, detail};
        mask_ |= uint32_t(1) << static_cast<unsigned>(e);
    }
    void finish(uint64_t now, int32_t reason) {
        put(Event::END, now, reason);
        active_ = false;
        ready_ = true;
    }
    void terminal(Event e, uint64_t now) {
        put(e, now, 0);
        finish(now, static_cast<int32_t>(e));
    }
    std::mutex mutex_;
    std::array<Row, 20> rows_{};
    uint64_t turn_ = 0, sequence_ = 0, start_ = 0;
    uint32_t mask_ = 0;
    std::size_t count_ = 0;
    bool active_ = false, ready_ = false, overflow_ = false;
};
}  // namespace a09

// ---- firmware/main/lab_latency.h ----
// SPDX-License-Identifier: MIT
#pragma once
#include <esp_log.h>
#include <esp_random.h>
#include <esp_timer.h>
#include "lab_latency_policy.h"
#if CONFIG_USE_AUDIO_PROCESSOR || !CONFIG_WAKE_WORD_DISABLED
#error \
    "A09 trace scope is the locked raw/manual configuration; re-evaluate epoch propagation for AFE/wake modes"
#endif
namespace a09 {
inline uint64_t now() { return static_cast<uint64_t>(esp_timer_get_time()); }
inline Recorder& recorder() {
    static Recorder r;
    return r;
}
inline uint64_t epoch() { return recorder().epoch(); }
inline void mark(uint64_t turn, Event event) { recorder().mark(turn, event, now()); }
inline void fail(Event event) { recorder().fail(event, now()); }
inline void fail_epoch(uint64_t turn, Event event) { recorder().fail_epoch(turn, event, now()); }
// Called by Application main-loop owner only, after a report has completed.
// UART is never written from an audio task, or while this measurement is active.
inline void flush() {
    recorder().poll(now());
    Report report;
    if (!recorder().take(report))
        return;
    static const uint32_t boot = esp_random();  // observation label, not authentication
    for (std::size_t i = 0; i < report.count; ++i) {
        const auto& r = report.rows[i];
        ESP_LOGI("a09", "A09v1 boot=%08lx seq=%llu turn=%llu event=%s us=%llu detail=%ld",
                 static_cast<unsigned long>(boot), static_cast<unsigned long long>(r.seq),
                 static_cast<unsigned long long>(r.turn), name(r.event),
                 static_cast<unsigned long long>(r.us), static_cast<long>(r.detail));
    }
    if (report.overflow)
        ESP_LOGE("a09", "A09v1_OVERFLOW boot=%08lx", static_cast<unsigned long>(boot));
}
}  // namespace a09

# ---- tools/analyze_trace.py ----
#!/usr/bin/env python3
# SPDX-License-Identifier: MIT
"""Analyze locally observed A09 stages; never derives server first-token/acoustic time."""
from pathlib import Path
import argparse,csv,hashlib,json,math,re,statistics
PATTERN=re.compile(r'A09v1 boot=([0-9a-f]{8}) seq=(\d+) turn=(\d+) event=([A-Z_]+) us=(\d+) detail=(-?\d+)(?:\s|$)')
EVENTS={'BEGIN','LISTEN_CMD_RETURN','MIC_CHUNK_RETURN','FIRST_SEND_RETURN','STOP_LISTEN_RETURN','STT_JSON','TTS_START_JSON','FIRST_TTS_SENTENCE_JSON','FIRST_TTS_AUDIO_CALLBACK','FIRST_PCM_WRITE_ENTER','FIRST_PCM_WRITE_RETURN','NETWORK_FAILURE','SEND_FAILURE','DECODE_QUEUE_REJECT','TIMEOUT','REENTRY','CLOCK_INVALID','END'}
METRICS={'setup_to_mic_ms':('BEGIN','MIC_CHUNK_RETURN'),'mic_to_send_call_return_ms':('MIC_CHUNK_RETURN','FIRST_SEND_RETURN'),'stop_to_subtitle_ms':('STOP_LISTEN_RETURN','FIRST_TTS_SENTENCE_JSON'),'stop_to_audio_callback_ms':('STOP_LISTEN_RETURN','FIRST_TTS_AUDIO_CALLBACK'),'audio_callback_to_pcm_call_return_ms':('FIRST_TTS_AUDIO_CALLBACK','FIRST_PCM_WRITE_RETURN'),'local_begin_to_pcm_call_return_ms':('BEGIN','FIRST_PCM_WRITE_RETURN')}
def load(path):
 data=path.read_text();turns={};seq={};boots=set()
 for number,line in enumerate(data.splitlines(),1):
  if 'A09v1_OVERFLOW' in line:raise ValueError(f'recorder overflow at line{number}; reject capture')
  if 'A09v1 'not in line:continue
  m=PATTERN.search(line)
  if not m:raise ValueError(f'malformed trace line{number}')
  boot,sequence,turn,event,us,detail=m.groups();sequence,turn,us,detail=map(int,(sequence,turn,us,detail));boots.add(boot)
  if event not in EVENTS or not 0<sequence<=0xffffffffffffffff or not 0<turn<=0xffffffffffffffff or us>0x7fffffffffffffff or not -0x80000000<=detail<=0x7fffffff:raise ValueError(f'event/range error line{number}')
  if boot in seq and sequence!=seq[boot]+1:raise ValueError(f'missing/duplicate/reordered serial sequence line{number}')
  seq[boot]=sequence;row=turns.setdefault((boot,turn),{})
  if event in row:raise ValueError(f'duplicate stage line{number}')
  row[event]=(us,detail)
 if len(boots)>1:raise ValueError('multiple boot labels: split captures and record resets in attempts.csv')
 rows=[]
 for (boot,turn),stages in turns.items():
  if 'BEGIN'not in stages or 'END'not in stages:raise ValueError('truncated turn: preserve raw file and recapture')
  begin=stages['BEGIN'][0];end,reason=stages['END'];failures={'NETWORK_FAILURE','SEND_FAILURE','DECODE_QUEUE_REJECT','TIMEOUT','REENTRY','CLOCK_INVALID'};status='complete'if reason==0 and'FIRST_PCM_WRITE_RETURN'in stages and not failures.intersection(stages) else'failed'
  if end<begin or any(us<begin or us>end for us,_ in stages.values()):raise ValueError('stage outside local window')
  values={};missing=[]
  for name,(a,b)in METRICS.items():
   if a not in stages or b not in stages:values[name]=None;missing.append(name)
   elif stages[b][0]<stages[a][0]:values[name]=None;missing.append(name+':ordering');status='ambiguous'
   else:values[name]=(stages[b][0]-stages[a][0])/1000
  rows.append({'boot':boot,'turn':turn,'status':status,'end_reason':reason,'missing':missing,**values})
 return rows

def percentile(values,p):
 values=sorted(values);position=(len(values)-1)*p;lo=math.floor(position);hi=math.ceil(position)
 return values[lo]+(values[hi]-values[lo])*(position-lo)
def main():
 parser=argparse.ArgumentParser(description=__doc__);parser.add_argument('capture',type=Path);parser.add_argument('--origin',choices=['serial-unverified','synthetic-fixture'],required=True);parser.add_argument('--attempts',type=Path);parser.add_argument('--min-complete',type=int,default=20);parser.add_argument('--output',type=Path,required=True);args=parser.parse_args()
 if args.min_complete<20:parser.error('min-complete must be at least20')
 if args.origin=='serial-unverified'and not args.attempts:parser.error('physical method requires the complete manual attempts.csv including reset/no-report rows')
 try:
  rows=load(args.capture);attempts=list(csv.DictReader(args.attempts.open(newline='')))if args.attempts else[]
  if args.attempts and len(attempts)<len(rows):raise ValueError('manual attempts cannot be fewer than reports')
 except (ValueError,OSError)as error:parser.exit(2,str(error)+'\n')
 complete=[r for r in rows if r['status']=='complete'];metrics={}
 for name in METRICS:
  values=[r[name]for r in complete if r[name]is not None]
  metrics[name]={'validSamples':len(values),'median':statistics.median(values)if len(values)>=args.min_complete else None,'p90':percentile(values,.9)if len(values)>=args.min_complete else None,'p95':percentile(values,.95)if len(values)>=args.min_complete else None}
 summary={'origin':args.origin,'physicalValidation':'not established by this tool; origin is a caller label','captureSha256':hashlib.sha256(args.capture.read_bytes()).hexdigest(),'reportedTurns':len(rows),'completeReports':len(complete),'completeDefinition':'normal END+firstPCMcallreturn withoutfailureevent; not allmetricstages, entireaudio, or successfuldialogue','failedOrAmbiguousReports':len(rows)-len(complete),'manualAttemptRows':len(attempts),'unreportedAttempts':len(attempts)-len(rows)if args.attempts else None,'minimumSamplesPerMetric':args.min_complete,'quantileMethod':'linear interpolation at (n-1)*p; failures/missing stages counted, not assigned zero','metrics':metrics,'turns':rows,'notMeasured':['server STT/LLM/TTS internals','server first token','acoustic onset','wireless ACK or remote receipt','trace probe overhead']}
 args.output.write_text(json.dumps(summary,ensure_ascii=False,indent=2)+'\n');print(json.dumps({k:summary[k]for k in ['origin','reportedTurns','completeReports','failedOrAmbiguousReports','manualAttemptRows','unreportedAttempts']},ensure_ascii=False));print(args.output)
if __name__=='__main__':main()