mplayer ktracing
In my ongoing quest to find the most inefficient software that still appears to work, I happened to notice that mplayer was chewing up 16% CPU while playing an MP3 (an audio format from the time before youtube). This was somewhat surprising because extrapolating back to the 20 year old computer I first used for MP3 listening, this would mean in excess of 100% CPU usage. Is efficient MP3 decoding really a lost art or was mplayer spending all its time doing something other than decoding? ktrace to the rescue.
83183 mplayer CALL select(1,0x7f7ffffc1f80,0,0,0x7f7ffffc1f70)
83183 mplayer STRU struct timeval { 0 }
83183 mplayer STRU struct fd_set { 0 }
83183 mplayer STRU struct fd_set { }
83183 mplayer RET select 0
83183 mplayer CALL poll(0x161b2123f330,1,0)
83183 mplayer STRU struct pollfd { fd=4, events=0x4<POLLOUT>, revents=0<> }
83183 mplayer RET poll 0
83183 mplayer CALL nanosleep(0x7f7ffffc2010,0)
83183 mplayer STRU struct timespec { 0.010000000 }
83183 mplayer RET nanosleep 0
83183 mplayer CALL poll(0x161b2123f330,1,0)
83183 mplayer STRU struct pollfd { fd=4, events=0x4<POLLOUT>, revents=0x4<POLLOUT> }
83183 mplayer RET poll 1
83183 mplayer CALL ioctl(4,AUDIO_GETPOS,0x7f7ffffc1f70)
83183 mplayer RET ioctl 0
83183 mplayer CALL gettimeofday(0x7f7ffffc2010,0)
83183 mplayer STRU struct timeval { 1486739185<"Feb 10 10:06:25 2017">.970769 }
83183 mplayer RET gettimeofday 0
83183 mplayer CALL gettimeofday(0x7f7ffffc2010,0)
83183 mplayer STRU struct timeval { 1486739185<"Feb 10 10:06:25 2017">.970812 }
83183 mplayer RET gettimeofday 0
83183 mplayer CALL write(4,0x161ac95a5000,0xe00)
83183 mplayer RET write 3584/0xe00
83183 mplayer CALL poll(0x161b2123f330,1,0)
83183 mplayer STRU struct pollfd { fd=4, events=0x4<POLLOUT>, revents=0<> }
83183 mplayer RET poll 0
83183 mplayer CALL ioctl(0,TIOCGWINSZ,0x7f7ffffc1fc8)
83183 mplayer RET ioctl 0
83183 mplayer CALL write(1,0x161b513a4000,0x2d)
83183 mplayer RET write 45/0x2d
83183 mplayer CALL gettimeofday(0x7f7ffffc1fb0,0)
83183 mplayer STRU struct timeval { 1486739185<"Feb 10 10:06:25 2017">.970936 }
83183 mplayer RET gettimeofday 0
83183 mplayer CALL select(1,0x7f7ffffc1f80,0,0,0x7f7ffffc1f70)
And, yeah, it’s not the greatest event loop. First we call select. Then we call poll. Why both? Why not pick one and pass it two file descriptors? Eh. Then since neither fd is ready, we call nanosleep to wait a bit. I’ll award a quarter point for not busy looping, but I’ll note that both poll and select take timeout arguments as well. Then it’s back to poll again. This entire mess could be a single call to poll.
Next we get into the meat. The audio out descriptor is finally ready, so we fiddle with that for a bit. Normally I’m pretty sad when I see tons of gettimeofday calls, but in a real time audio application, precise time keeping seems important so I’ll give mplayer a pass here.
Finally we print the status line to the terminal. I think the status line itself is a little excessive, but we’re here to discuss badly implemented features, not bad features. Along those lines, there’s no need to check via ioctl whether the terminal size has changed before every output. There’s a signal for that, SIGWINCH. Signals are in general a pretty poor IPC mechanism, and most of them are useless in today’s environments, but SIGWINCH stands out as a shining star. It’s the one signal that actually relays interesting information. Use it!
And then we’re back to our quad damage select/poll/nanosleep/poll event loop.
I was a little surprised by how many syscalls mplayer is making here. It’s not a browser with a hundred threads trying to multiplex a dozen inputs, but we’re talking about over 1000 syscalls per second. No wonder CPU load is high. FWIW, ffplay is much more efficient, but only after disabling the histogram thing it wants to draw in another window. I imagine old standbys like mpg123 are better still. I moved on because my media collection is now in a dozen different formats, but that could be worth reconsidering.
Tagged: software