Rockbox

Possibly related to  FS#8964 

Additional information:
- I was wrong: It also happens with VBR files, but not with all albums though. I wasn't able to figure out the difference yet.
- It also happens if the 1st track is very short, so that the 2nd track starts while still buffering.
- It doesn't matter whether or not album art is present.

I've observed stray boost on the audio thread as well recently ("+" remaining next to the thread in View OS Stacks).

I don't really understand the issue here… I've posted a patch in  FS#8964 . Does it fix this issue too by any chance?

Unfortunately the patch for  FS#8964  doesn't fix this one.

I was able to track it down to a point where tracks[track_widx].id3_hid is -1 in buffering_handle_finished_callback(). That's probably wrong and causes buffering to stop prematurely because Q_AUDIO_FINISH_LOAD is not fired. But here I stuck.
Attached are two logf dumps with and without skipping the first track. I added two logf lines in buffering_handle_finished_callback() below the existing:
logf("handle %d finished buffering", *data);
logf(" track_widx=%d", track_widx);
logf(" id3_hid=%d", tracks[track_widx].id3_hid);
Hope this helps.

   logf_noskip.txt (2.4 KiB)
   logf_skip.txt (1.5 KiB)

Thanks for the details, you've already found a lot. I'll try to investigate this ASAP.

I see a problem with my X5 witch is probabely related to this bug.

When i have "Gather Runtime Data" enabled, sometimes the CPU stays boosted when one track ends and the next starts. I dont have to skip. What i also see is, that the buffers are not filled up.

With "Gather Runtime Data" disabled everything works fine, and i am not able to reproduce the bug.

It looks like, that the writing of the runtime data disturbes the reding of the mp3-file.

I have this problem also with gather runtime data turned off, but only when i am navigating arrount in the database (with dbcache turned off) and modify the playlist while the buffers are filled up. It looks like that the fill up of the buffers stop at the end of a track.

I enhanced the logging a bit and attache the logfiles to this message. I hope, that the logs are usefull for someone.

   logf.without-gather-runtime-d... (85 KiB)
   logf.with-gather-runtime-data... (84.7 KiB)

Nicolas, I think this bug is related to one I filed recently,  FS#9576  and I narrowed the problem down to being introduced between r17103 and r17111. I have not yet tested the builds between those, but right now I suspect the problem was introduced in your buffering rework patch committed in r17109. I'm trying to set up a dev env now to verify.

Does this still happen after r19304, which is supposed to have fixed  FS#9576 ?

Yes, this one is not the same issue and I still haven't managed to find the cause of it, despite having investigated a few days ago.

The "stays boosted" portion should be fixed, but I think the buffer still doesn't advance sometimes

No, I can still reproduce also the "stays boosted" portion. But you have to skip quite quickly now, as buffering has become much faster due to the various optimizations in the meantime.