Add comprehensive debug logging and performance monitoring

Added detailed terminal output to diagnose video loading hangs:
- Session creation logging (resolution, fps, target size)
- FFmpeg command logging
- Frame decode pipeline timing (first frame, decode time, render time)
- Real-time FPS counter (reports every 2 seconds)
- Memory usage info (frame buffer size)
- Error reporting with FFmpeg stderr output

This will help identify performance bottlenecks and hanging issues
during video playback.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-Authored-By: Claude Sonnet 4.5 <noreply@anthropic.com>
This commit is contained in:
Stu 2025-12-09 16:09:02 -05:00
parent 998b76cefd
commit c4a5e48a22

75
main.go
View File

@ -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 { 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 { if fps <= 0 {
fps = 24 fps = 24
} }
@ -3687,12 +3695,15 @@ func newPlaySession(path string, w, h int, fps float64, targetW, targetH int, pr
} }
func (p *playSession) Play() { func (p *playSession) Play() {
fmt.Printf("▶️ PLAY called (current position: %.2fs)\n", p.current)
p.mu.Lock() p.mu.Lock()
defer p.mu.Unlock() defer p.mu.Unlock()
if p.videoCmd == nil && p.audioCmd == nil { if p.videoCmd == nil && p.audioCmd == nil {
fmt.Printf("⚡ Starting playback from scratch...\n")
p.startLocked(p.current) p.startLocked(p.current)
return return
} }
fmt.Printf("▶️ Resuming playback\n")
p.paused = false p.paused = false
} }
@ -3821,6 +3832,11 @@ func (p *playSession) startLocked(offset float64) {
} }
func (p *playSession) runVideo(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 var stderr bytes.Buffer
args := []string{ args := []string{
"-hide_banner", "-loglevel", "error", "-hide_banner", "-loglevel", "error",
@ -3832,17 +3848,29 @@ func (p *playSession) runVideo(offset float64) {
"-r", fmt.Sprintf("%.3f", p.fps), "-r", fmt.Sprintf("%.3f", p.fps),
"-", "-",
} }
fmt.Printf("🔧 FFmpeg command: ffmpeg %s\n", strings.Join(args, " "))
cmd := exec.Command("ffmpeg", args...) cmd := exec.Command("ffmpeg", args...)
cmd.Stderr = &stderr cmd.Stderr = &stderr
stdout, err := cmd.StdoutPipe() stdout, err := cmd.StdoutPipe()
if err != nil { if err != nil {
fmt.Printf("❌ ERROR: Failed to create video pipe: %v\n", err)
logging.Debug(logging.CatFFMPEG, "video pipe error: %v", err) logging.Debug(logging.CatFFMPEG, "video pipe error: %v", err)
return return
} }
fmt.Printf("⚡ Starting FFmpeg process...\n")
startTime := time.Now()
if err := cmd.Start(); err != nil { 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 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. // Pace frames to the source frame rate instead of hammering refreshes as fast as possible.
frameDur := time.Second frameDur := time.Second
if p.fps > 0 { if p.fps > 0 {
@ -3852,11 +3880,22 @@ func (p *playSession) runVideo(offset float64) {
p.videoCmd = cmd p.videoCmd = cmd
frameSize := p.targetW * p.targetH * 3 frameSize := p.targetW * p.targetH * 3
buf := make([]byte, frameSize) buf := make([]byte, frameSize)
fmt.Printf("📦 Frame buffer allocated: %.2f MB\n", float64(frameSize)/(1024*1024))
go func() { go func() {
defer cmd.Process.Kill() 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 { for {
select { select {
case <-p.stop: case <-p.stop:
fmt.Printf("⏹️ Video decode loop stopped\n")
logging.Debug(logging.CatFFMPEG, "video loop stop") logging.Debug(logging.CatFFMPEG, "video loop stop")
return return
default: default:
@ -3866,22 +3905,41 @@ func (p *playSession) runVideo(offset float64) {
nextFrameAt = time.Now().Add(frameDur) nextFrameAt = time.Now().Add(frameDur)
continue continue
} }
readStart := time.Now()
_, err := io.ReadFull(stdout, buf) _, err := io.ReadFull(stdout, buf)
readDuration := time.Since(readStart)
if err != nil { if err != nil {
if errors.Is(err, io.EOF) { if errors.Is(err, io.EOF) {
fmt.Printf("📺 Video playback completed (reached end)\n")
return return
} }
msg := strings.TrimSpace(stderr.String()) 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) logging.Debug(logging.CatFFMPEG, "video read failed: %v (%s)", err, msg)
return 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 { if delay := time.Until(nextFrameAt); delay > 0 {
time.Sleep(delay) time.Sleep(delay)
} }
nextFrameAt = nextFrameAt.Add(frameDur) nextFrameAt = nextFrameAt.Add(frameDur)
// Allocate a fresh frame to avoid concurrent texture reuse issues. // Allocate a fresh frame to avoid concurrent texture reuse issues.
frame := image.NewRGBA(image.Rect(0, 0, p.targetW, p.targetH)) frame := image.NewRGBA(image.Rect(0, 0, p.targetW, p.targetH))
utils.CopyRGBToRGBA(frame.Pix, buf) utils.CopyRGBToRGBA(frame.Pix, buf)
renderStart := time.Now()
fyne.CurrentApp().Driver().DoFromGoroutine(func() { fyne.CurrentApp().Driver().DoFromGoroutine(func() {
if p.img != nil { if p.img != nil {
// Ensure we render the live frame, not a stale resource preview. // Ensure we render the live frame, not a stale resource preview.
@ -3891,10 +3949,25 @@ func (p *playSession) runVideo(offset float64) {
p.img.Refresh() p.img.Refresh()
} }
}, false) }, false)
renderDuration := time.Since(renderStart)
// Log first few frames in detail
if p.frameN < 3 { 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) logging.Debug(logging.CatFFMPEG, "video frame %d drawn (%.2fs)", p.frameN+1, p.current)
} }
p.frameN++ 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 { if p.fps > 0 {
p.current = offset + (float64(p.frameN) / p.fps) p.current = offset + (float64(p.frameN) / p.fps)
} }