diff --git a/main.go b/main.go index a6995b0..40b5ce0 100644 --- a/main.go +++ b/main.go @@ -3662,6 +3662,14 @@ func getAudioContext(sampleRate, channels, bytesPerSample int) (*oto.Context, er } func newPlaySession(path string, w, h int, fps float64, targetW, targetH int, prog func(float64), img *canvas.Image) *playSession { + fmt.Printf("\n═══════════════════════════════════════════════════════\n") + fmt.Printf("🎬 CREATING NEW PLAY SESSION\n") + fmt.Printf("═══════════════════════════════════════════════════════\n") + fmt.Printf("📁 Video: %s\n", filepath.Base(path)) + fmt.Printf("📐 Source: %dx%d @ %.2f fps\n", w, h, fps) + fmt.Printf("🎯 Target: %dx%d\n", targetW, targetH) + fmt.Printf("═══════════════════════════════════════════════════════\n\n") + if fps <= 0 { fps = 24 } @@ -3687,12 +3695,15 @@ func newPlaySession(path string, w, h int, fps float64, targetW, targetH int, pr } func (p *playSession) Play() { + fmt.Printf("▶️ PLAY called (current position: %.2fs)\n", p.current) p.mu.Lock() defer p.mu.Unlock() if p.videoCmd == nil && p.audioCmd == nil { + fmt.Printf("⚡ Starting playback from scratch...\n") p.startLocked(p.current) return } + fmt.Printf("▶️ Resuming playback\n") p.paused = false } @@ -3821,6 +3832,11 @@ func (p *playSession) startLocked(offset float64) { } func (p *playSession) runVideo(offset float64) { + fmt.Printf("📹 Starting video decode pipeline...\n") + fmt.Printf(" - Resolution: %dx%d\n", p.targetW, p.targetH) + fmt.Printf(" - Frame rate: %.2f fps\n", p.fps) + fmt.Printf(" - Offset: %.2fs\n", offset) + var stderr bytes.Buffer args := []string{ "-hide_banner", "-loglevel", "error", @@ -3832,17 +3848,29 @@ func (p *playSession) runVideo(offset float64) { "-r", fmt.Sprintf("%.3f", p.fps), "-", } + fmt.Printf("🔧 FFmpeg command: ffmpeg %s\n", strings.Join(args, " ")) + cmd := exec.Command("ffmpeg", args...) cmd.Stderr = &stderr stdout, err := cmd.StdoutPipe() if err != nil { + fmt.Printf("❌ ERROR: Failed to create video pipe: %v\n", err) logging.Debug(logging.CatFFMPEG, "video pipe error: %v", err) return } + + fmt.Printf("⚡ Starting FFmpeg process...\n") + startTime := time.Now() if err := cmd.Start(); err != nil { - logging.Debug(logging.CatFFMPEG, "video start failed: %v (%s)", err, strings.TrimSpace(stderr.String())) + errMsg := strings.TrimSpace(stderr.String()) + fmt.Printf("❌ ERROR: FFmpeg failed to start: %v\n", err) + if errMsg != "" { + fmt.Printf(" FFmpeg error: %s\n", errMsg) + } + logging.Debug(logging.CatFFMPEG, "video start failed: %v (%s)", err, errMsg) return } + fmt.Printf("✅ FFmpeg started in %.3fs\n", time.Since(startTime).Seconds()) // Pace frames to the source frame rate instead of hammering refreshes as fast as possible. frameDur := time.Second if p.fps > 0 { @@ -3852,11 +3880,22 @@ func (p *playSession) runVideo(offset float64) { p.videoCmd = cmd frameSize := p.targetW * p.targetH * 3 buf := make([]byte, frameSize) + fmt.Printf("📦 Frame buffer allocated: %.2f MB\n", float64(frameSize)/(1024*1024)) + go func() { defer cmd.Process.Kill() + + // Performance monitoring variables + var lastFPSReport time.Time + var fpsCounter int + loopStart := time.Now() + + fmt.Printf("🔄 Frame decode loop started\n") + for { select { case <-p.stop: + fmt.Printf("⏹️ Video decode loop stopped\n") logging.Debug(logging.CatFFMPEG, "video loop stop") return default: @@ -3866,22 +3905,41 @@ func (p *playSession) runVideo(offset float64) { nextFrameAt = time.Now().Add(frameDur) continue } + + readStart := time.Now() _, err := io.ReadFull(stdout, buf) + readDuration := time.Since(readStart) + if err != nil { if errors.Is(err, io.EOF) { + fmt.Printf("📺 Video playback completed (reached end)\n") return } msg := strings.TrimSpace(stderr.String()) + fmt.Printf("❌ ERROR: Frame read failed: %v\n", err) + if msg != "" { + fmt.Printf(" FFmpeg error: %s\n", msg) + } logging.Debug(logging.CatFFMPEG, "video read failed: %v (%s)", err, msg) return } + + // Track first frame timing + if p.frameN == 0 { + elapsed := time.Since(loopStart) + fmt.Printf("🎞️ FIRST FRAME decoded in %.3fs (read: %.3fs)\n", elapsed.Seconds(), readDuration.Seconds()) + } + if delay := time.Until(nextFrameAt); delay > 0 { time.Sleep(delay) } nextFrameAt = nextFrameAt.Add(frameDur) + // Allocate a fresh frame to avoid concurrent texture reuse issues. frame := image.NewRGBA(image.Rect(0, 0, p.targetW, p.targetH)) utils.CopyRGBToRGBA(frame.Pix, buf) + + renderStart := time.Now() fyne.CurrentApp().Driver().DoFromGoroutine(func() { if p.img != nil { // Ensure we render the live frame, not a stale resource preview. @@ -3891,10 +3949,25 @@ func (p *playSession) runVideo(offset float64) { p.img.Refresh() } }, false) + renderDuration := time.Since(renderStart) + + // Log first few frames in detail if p.frameN < 3 { + fmt.Printf("🖼️ Frame %d: decode=%.3fs render=%.3fs\n", p.frameN+1, readDuration.Seconds(), renderDuration.Seconds()) logging.Debug(logging.CatFFMPEG, "video frame %d drawn (%.2fs)", p.frameN+1, p.current) } + p.frameN++ + fpsCounter++ + + // FPS report every 2 seconds + if time.Since(lastFPSReport) >= 2*time.Second { + fps := float64(fpsCounter) / time.Since(lastFPSReport).Seconds() + fmt.Printf("📊 Performance: %.1f FPS (target: %.1f FPS) | Frames: %d\n", fps, p.fps, p.frameN) + fpsCounter = 0 + lastFPSReport = time.Now() + } + if p.fps > 0 { p.current = offset + (float64(p.frameN) / p.fps) }