Update app.py

app.py

@@ -61,16 +61,21 @@ async def generate_greeting():
 
     try:
         from tts import generate_audio
+        t_tts = _time.time()
         audio_path = generate_audio(greeting_text)
+        t_tts_done = _time.time()
+        logger.info(f"[{_ts()}] [GREETING] TTS: {t_tts_done-t_tts:.2f}s")
         audio_url = None
         audio_duration = 0
 
         if audio_path and os.path.exists(audio_path):
             audio_url = f"/api/audio/{os.path.basename(audio_path)}"
+            logger.info(f"[{_ts()}] [GREETING] Audio: {os.path.getsize(audio_path)/1024:.0f}KB")
             try:
                 r = subprocess.run(["ffprobe", "-v", "quiet", "-show_entries", "format=duration",
                                     "-of", "csv=p=0", audio_path], capture_output=True, text=True, check=True)
                 audio_duration = float(r.stdout.strip())
+                logger.info(f"[{_ts()}] [GREETING] Audio duration: {audio_duration:.1f}s")
             except Exception:
                 audio_duration = 5.0
 
@@ -80,9 +85,13 @@ async def generate_greeting():
                 from float_lipsync import get_lipsync
                 lipsync = get_lipsync()
                 if lipsync.ready:
+                    t_float = _time.time()
                     lp = lipsync.generate(audio_path)
+                    t_float_done = _time.time()
+                    logger.info(f"[{_ts()}] [GREETING] FLOAT: {t_float_done-t_float:.2f}s")
                     if lp and os.path.exists(lp):
                         lipsync_video_url = f"/api/stream/{os.path.basename(lp)}"
+                        logger.info(f"[{_ts()}] [GREETING] Video: {os.path.getsize(lp)/1024:.0f}KB")
             except Exception as e:
                 logger.warning(f"[GREETING] FLOAT failed, greeting will be text-only: {e}")
 
@@ -275,6 +284,7 @@ async def chat_next(request: Request):
     Generate TTS + lipsync for the next sentence in the session.
     Heavy work runs in a thread so the server stays responsive for prefetch requests.
     """
+    t_req = _time.time()
     body = await request.json()
     session_id = body.get("session_id", "")
     session = _sessions.get(session_id)
@@ -292,10 +302,15 @@ async def chat_next(request: Request):
     is_last = (idx + 1 >= session["total"])
     total = session["total"]
 
+    logger.info(f"[{_ts()}] [REQ] /api/chat/next chunk {idx+1}/{total} received")
+
     # Run the heavy TTS + FLOAT work in a thread
     import asyncio
     result = await asyncio.to_thread(_generate_chunk, sentence, idx, total)
 
+    t_resp = _time.time()
+    logger.info(f"[{_ts()}] [REQ] /api/chat/next chunk {idx+1}/{total} responding | request-to-response: {t_resp-t_req:.2f}s")
+
     if is_last:
         session["done"] = True
         if len(_sessions) > 10:
@@ -317,26 +332,33 @@ async def chat_next(request: Request):
 
 def _generate_chunk(sentence, idx, total):
     """Synchronous TTS + FLOAT generation (runs in thread pool)."""
-    logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] {sentence[:60]}...")
+    logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] START | \"{sentence[:80]}\"")
     t0 = _time.time()
 
-    # 1. TTS
+    # 1. TTS API call
     from tts import generate_audio
-    t1 = _time.time()
+    t_tts_start = _time.time()
     audio_path = generate_audio(sentence)
-    t2 = _time.time()
-    logger.info(f"[{_ts()}] [TIMING] Chunk {idx+1} TTS: {t2-t1:.2f}s")
-
+    t_tts_end = _time.time()
+    
     audio_url = None
     audio_duration = 0
+    audio_size = 0
     if audio_path and os.path.exists(audio_path):
+        audio_size = os.path.getsize(audio_path)
         audio_url = f"/api/audio/{os.path.basename(audio_path)}"
+        t_probe_start = _time.time()
         try:
             r = subprocess.run(["ffprobe","-v","quiet","-show_entries","format=duration",
                                 "-of","csv=p=0", audio_path], capture_output=True, text=True, check=True)
             audio_duration = float(r.stdout.strip())
         except Exception:
             audio_duration = 3.0
+        t_probe_end = _time.time()
+    else:
+        t_probe_start = t_probe_end = _time.time()
+
+    logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] TTS: {t_tts_end-t_tts_start:.2f}s | audio: {audio_duration:.1f}s, {audio_size/1024:.0f}KB | ffprobe: {t_probe_end-t_probe_start:.3f}s")
 
     # 2. Lipsync (locked — GPU not thread-safe)
     lipsync_video_url = None
@@ -345,18 +367,25 @@ def _generate_chunk(sentence, idx, total):
             from float_lipsync import get_lipsync
             lipsync = get_lipsync()
             if lipsync.ready:
+                t_lock_wait = _time.time()
                 with _float_lock:
-                    t3 = _time.time()
+                    t_lock_acquired = _time.time()
+                    lock_wait = t_lock_acquired - t_lock_wait
+                    if lock_wait > 0.01:
+                        logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] LOCK WAIT: {lock_wait:.2f}s")
                     lp = lipsync.generate(audio_path)
-                    t4 = _time.time()
-                logger.info(f"[{_ts()}] [TIMING] Chunk {idx+1} FLOAT: {t4-t3:.2f}s")
+                    t_float_done = _time.time()
+                float_time = t_float_done - t_lock_acquired
+                logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] FLOAT: {float_time:.2f}s (lock wait: {lock_wait:.2f}s)")
                 if lp and os.path.exists(lp):
+                    lp_size = os.path.getsize(lp)
                     lipsync_video_url = f"/api/stream/{os.path.basename(lp)}"
+                    logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] VIDEO: {lp_size/1024:.0f}KB")
         except Exception as e:
-            logger.error(f"[{_ts()}] [CHUNK] Lipsync failed: {e}", exc_info=True)
+            logger.error(f"[{_ts()}] [CHUNK {idx+1}/{total}] LIPSYNC FAILED: {e}", exc_info=True)
 
     total_time = _time.time() - t0
-    logger.info(f"[{_ts()}] [TIMING] Chunk {idx+1} TOTAL: {total_time:.2f}s")
+    logger.info(f"[{_ts()}] [CHUNK {idx+1}/{total}] DONE | total: {total_time:.2f}s | tts: {t_tts_end-t_tts_start:.2f}s + float: {total_time-(t_tts_end-t_tts_start):.2f}s")
 
     return {
         "audio_url": audio_url,
@@ -590,14 +619,45 @@ async function sendMessage(){
         if(!res.ok) throw new Error('HTTP '+res.status);
         const data=await res.json();
 
-        // Show full text immediately
+        // Replace typing indicator with empty bot bubble, ready for streaming
         typing.bubbleEl.classList.remove('typing');
         typing.contentEl.classList.remove('typing-dots');
-        typing.contentEl.textContent=data.text;
-        chatLog.scrollTop=chatLog.scrollHeight;
+        typing.contentEl.textContent='';
+        typing.contentEl.classList.add('streaming-cursor');
 
         const sessionId=data.session_id;
         const totalChunks=data.total_chunks;
+        const fullText=data.text;
+        const words=fullText.split(/\s+/);
+        let wordsShown=0;
+
+        // Text streaming: reveal words over the given duration
+        function streamText(durationSec){
+            const wordsToShow=words.length - wordsShown;
+            if(wordsToShow<=0) return Promise.resolve();
+            const interval=Math.max(50, (durationSec*1000)/wordsToShow);
+            return new Promise((resolve)=>{
+                let i=0;
+                const timer=setInterval(()=>{
+                    if(i>=wordsToShow){
+                        clearInterval(timer);
+                        resolve();
+                        return;
+                    }
+                    wordsShown++;
+                    typing.contentEl.textContent=words.slice(0,wordsShown).join(' ');
+                    chatLog.scrollTop=chatLog.scrollHeight;
+                    i++;
+                }, interval);
+            });
+        }
+
+        // Show all remaining text instantly (cleanup)
+        function showAllText(){
+            typing.contentEl.textContent=fullText;
+            typing.contentEl.classList.remove('streaming-cursor');
+            chatLog.scrollTop=chatLog.scrollHeight;
+        }
 
         videoStatus.textContent='generating 1/'+totalChunks+'...';
 
@@ -644,6 +704,10 @@ async function sendMessage(){
                 });
             }
 
+            // Stream text for this chunk's duration
+            const chunkDuration=chunk.audio_duration||3.0;
+            const textStreamPromise=streamText(chunkDuration);
+
             // Play lipsync video
             if(chunk.lipsync_video_url){
                 await crossfadeTo(chunk.lipsync_video_url, true);
@@ -653,8 +717,14 @@ async function sendMessage(){
                 // No lipsync, just wait for audio to finish
                 await audioPromise;
             }
+
+            // Ensure text streaming for this chunk is done
+            await textStreamPromise;
         }
 
+        // Ensure all text is shown
+        showAllText();
+
         // All chunks done, return to idle
         isSpeaking=false;
         playNextIdle();
@@ -663,6 +733,7 @@ async function sendMessage(){
         typing.bubbleEl.classList.remove('typing');
         typing.bubbleEl.classList.add('error');
         typing.contentEl.classList.remove('typing-dots');
+        typing.contentEl.classList.remove('streaming-cursor');
         typing.contentEl.textContent='Error: '+err.message;
     }
     isSpeaking=false; isProcessing=false; btnSend.disabled=false; chatInput.focus();