One small step for ffmpeg... one giant leap for Emby! (Looking for C developer(s) to help with transcode throttling)

[FredipusRex 12]

Although this is really small potatoes, I should have called the new variables pause_start and paused_time to be consistent with their naming convention. OSS folks can be pretty prickly about coding standards.

 

I purposely avoided an av_ prefix on the gettime_relative_minus_pause() because av_ only seems to be used within their avxxx libraries.

[jluce50 118]

Yeah, after reading through their docs and the dev mailing list, they're doing their part to conform to that stereotype . I thought about adding gettime_relative_minus_pause() to time.c (with the other av_* time-related methods), but I went ahead and left it local.

[FredipusRex 12]

FYI - I created a proper patch file based on the current trunk ffmpeg.c. It only modifies two existing lines and adds about 20 lines of new code. It's in WinMerge format. Feel free to use or discard.

 

148a149,151
> int64_t     pause_start = 0;
> int64_t     paused_time = 0;
>
3270a3274,3279
>     if ((key != -1 || key == 'u') && pause_start)
>     {
>         paused_time += av_gettime_relative() - pause_start;
>         pause_start = 0;
>     }
>     if (key == 'p' && !pause_start) pause_start = av_gettime_relative();
3348a3358
>                         "p      pause transcoding\n"
3349a3360
>                         "u      unpause transcoding\n"
3492a3504,3511
>  * Return the current time minus any time spent or being spent in a paused state
>  */
> static int64_t gettime_relative_minus_pause()
> {
>     return av_gettime_relative() - paused_time - (pause_start ? av_gettime_relative() - pause_start : 0);
> }
>
> /*
3780a3800,3805
>     if (pause_start)
>     {
>         av_usleep(10000);
>         return 0;
>     }
>     
3841c3866
<         int64_t cur_time= av_gettime_relative();
---
>         int64_t cur_time= gettime_relative_minus_pause();
3888c3913
<     print_report(1, timer_start, av_gettime_relative());
---
>     print_report(1, timer_start, gettime_relative_minus_pause());

[jluce50 118]

Thanks. That's almost exactly what I've got now. I'm currently working through some issues with losing keyboard interaction. Not sure what's breaking it and troubleshooting is slow going...

[jluce50 118]

Okay, I think I got it. This change was breaking check_keyboard_interaction().

3841c3866
<         int64_t cur_time= av_gettime_relative();
---
>         int64_t cur_time= gettime_relative_minus_pause();

Edited March 6, 2015 by jluce50

[FredipusRex 12]

 

Okay, I think I got it. This change was breaking check_keyboard_interaction().

3841c3866
<         int64_t cur_time= av_gettime_relative();
---
>         int64_t cur_time= gettime_relative_minus_pause();

In what way? If we don't use the "pause adjusted time", we'll have the problem of unwanted logging during the pause. Unless we're just talking a typo?

[jluce50 118]

cur_time was passed into check_keyboard_interaction(), which waits a certain amount of time before accepting subsequent keypresses. Since that time wasn't changing while paused, it wasn't accepting any other inputs.

 

I reverted the line above and then just pass the result of gettime_relative_minus_pause() into print_report() and that seems to have fixed it.

[jluce50 118]

I'm getting pretty close, I think. Would you (@@FredipusRex... and possibly @@cayars ) mind taking a look at my changes before I submit it? I'd like to do whatever we can to minimize the chances of them rejecting it...

 

Also, if anyone is running linux and wants to see it in action, let me know and I can send you the executable.

Edited March 6, 2015 by jluce50

[FredipusRex 12]

cur_time was passed into check_keyboard_interaction(), which waits a certain amount of time before accepting subsequent keypresses. Since that time wasn't changing while paused, it wasn't accepting any other inputs.

 

I reverted the line above and then just pass the result of gettime_relative_minus_pause() into print_report() and that seems to have fixed it.

Gotcha, but you should swap that - set cur_time to gettime_relative_minus_pause() and pass in av_gettime_relative() to check_keyboard_interaction.

 

The reason is that cur_time is captured before a transcode_step (which is what takes time), so the print_report when unpaused needs to have a before transcode_step time stamp. This lets the print_report call figure out how long the previous step took (it's kind of backward so that the final call flushes everything out).

 

This combination will let the keyboard work while preserving the cl output.

[Carlo 4330]

Sent a PM with a couple of other things to look at.

[jluce50 118]

Gotcha, but you should swap that - set cur_time to gettime_relative_minus_pause() and pass in av_gettime_relative() to check_keyboard_interaction.

 

The reason is that cur_time is captured before a transcode_step (which is what takes time), so the print_report when unpaused needs to have a before transcode_step time stamp. This lets the print_report call figure out how long the previous step took (it's kind of backward so that the final call flushes everything out).

 

This combination will let the keyboard work while preserving the cl output.

 

Yeah, they way they're doing this seems a little jenky.

 

I'm not sure I understand why we need a before transcode_step() timestamp when unpaused. If we do that then the first call to print_report() after unpausing will see the frames processed in the most recent transcode_step() but have the relative timestamp from before that processing was done. The processing time elapsed is out of sync with the number of frames processed. That's actually the case whether we were paused or not. Unless I'm missing something, which is entirely possible, this almost sounds like a bug in the existing functionality. Why is fps calculated using the current number of frames processed and a timestamp from before the processing was done?

 

The logic of print_report() is like this: Calculate FPS based on the total number of frames processed and the total processing time (time between start and now, both of which are passed in). Only "now" isn't really now, it's "now" before the most recent transcode step. Adding the pause functionality doesn't really change anything. We're just adding the extra step of subtracting "time paused" from "between start and now". The problem is that the time spent in the most recent transcode step is not included in the calculation.

 

The way I have it makes more sense to me, personally. Each call to print_report() in the loop is using the current relative timestamp so it reflects the time spent in the most recent transcode_step() and the final call only includes time spent doing cleanup.

 

I was up late and my coffee hasn't kicked in yet, so please let me know if I've missed something here...

Edited March 7, 2015 by jluce50

[FredipusRex 12]

(Note: I've edited a line that I missed)

 

My concern is to leave the existing processing alone as much as possible - that there must be reasons that they coded things the way they did. And, you will notice that in the existing ffmpeg codebase, they grab the cur_time timestamp before the transcode_step() call. You've now moved that to after which is bound to have an impact.

 

The pattern is "grab time, do a really expensive transcode, log something". What they are doing is actually logging the previous transcode step, not the current one. They do this so that the final print_report (the summary) can spit out the final transcode time too.

 

Think of it in terms of an transcode that takes three iterations:

 

Setup: timer_start = 0ns

 

1. cur_time=0001ns, transcode_step (takes 1000ns), print_report(0, 0, 0001) --> hmm, nothing to print. Set last_time=0001

2. cur_time=1001ns, transcode_step (takes 1000ns), print_report(0, 0, 1001) --> Hey, it's been 1000ns since last_time, print something and set last_time=1001

3. cur_time=2002ns, transcode_step (takes 1000ns), print_report(0, 0, 2002) --> Hey, it's been 1001ns since last_time, print something and set last_time=2002

 

Cleanup: print_report(1, 0, 3003 "now") --> Oh, we're done. Print out whatever is left and output a summary

 

It makes more sense if individual transcode_steps don't always trigger a log line (the time taken to transcode fell below the logging threshold).

 

So we need to respect that workflow. But check_keyboard_interaction needs to deal with "real" time, so we have to tweak that too. Change the following lines:

int64_t cur_time= av_gettime_relative();

 

to

 

int64_t cur_time= gettime_relative_minus_pause();

 

and

 

if (check_keyboard_interaction(cur_time) < 0)

 

to

 

if (check_keyboard_interaction(av_gettime_relative()) < 0)

 

And revert:

 

print_report(0, timer_start, gettime_relative_minus_pause());

 

to

 

print_report(0, timer_start, cur_time);

 

That will respect the current output workflow while handling the "lost" pause time.

Edited March 7, 2015 by FredipusRex

[Luke 37090]

My concern is to leave the existing processing alone as much as possible.

 

Agree on this.

[jluce50 118]

Yeah, you're right. We probably shouldn't go messing with stuff that isn't strictly relevant. It turns out that f there is some sort of bug, the fix should actually be submitted in a separate pull request anyway (per their standards). Perhaps I can just ask via comment for clarification on how the logging works to satisfy my own curiosity.

 

The following is just for the sake of discussion since we won't be modifying the current logic...

 

The pattern is "grab time, do a really expensive transcode, log something". What they are doing is actually logging the previous transcode step, not the current one. They do this so that the final print_report (the summary) can spit out the final transcode time too.

 

The part that I'm getting hung up on is that there are two time values used to calculate FPS; start and end. The "end" time being used (cur_time) is grabbed before the processing for each iteration is done. So the time component of the calculation IS from the previous step, but the data (frames processed) in the calculation is from the CURRENT step since it's referenced after transcode_step().

 

Think of it like this (and I'm using seconds just to make this easier):

1. cur_time=0s, transcode_step (takes 1s), frames processed=1, print_report(0, 0, 0) --> hmm, nothing to print. Set last_time=0

2. cur_time=1s, transcode_step (takes 1s), frames processed=2, print_report(0, 0, 1) --> (1 - 0 ) / 2 = .5 fps

3. cur_time=2s, transcode_step (takes 1s), frames processed=3, print_report(0, 0, 2) --> (2 - 0) / 3 = .67 fps

 

I would think it should be like this:

1. transcode_step (takes 1s), frames processed=1, cur_time=1s, print_report(0, 0, 1) --> (1 - 0) / 1 = 1 fps

2. transcode_step (takes 1s), frames processed=2, cur_time=2s, print_report(0, 0, 2) --> (2 - 0 ) / 2 = 1 fps

3. transcode_step (takes 1s), frames processed=3, cur_time=3s, print_report(0, 0, 3) --> (3 - 0) / 3 = 1 fps

 

Yes, that would screw up the final report, but that's fairly easy to fix. Now you're probably right that they have it like it is for a reason and there's just some logic I'm missing somewhere. Perhaps the current frame_number of the output stream isn't incremented until subsequent steps? That would be a little odd, but who knows....

[Carlo 4330]

This is probably dumb for asking but I've only briefly looked over the code changes:

How is the actual pausing done in ffmpeg?

Are you sure it's pausing all threads and not just the thread the gui/entry is using?

[FredipusRex 12]

@@cayars - There is a multithreaded mode in the code but it seems to be optional. It's kind of unclear how that bit works but I confess to not spending a lot of time looking at it as it didn't seem relevant to the needs of MB3.

 

The main transcoding occurs in the transcode() function, which is basically a loop that checks the keyboard, transcodes some frames (transcode_step) and calls the logger. Once all input and output streams are done, the loop exits.

 

The loop code already has a mode that deals with temporary loss of the ability to output (network errors, I assume). The transcode_step checks if the output is available and if not, it sleeps a while and returns an 'OK'. The loop code will then continue, doing the logging step, checking the keyboard and calling transcode_step again.

 

I simply figured we could plug into that ability without modifying (or caring) how the real work is done. I essentially just added another "error" state (paused) and performed the same sleep/OK bit as the output checker did. Added some code to deal with the lost pause time and keys to pause/unpause and that's it.

 

It's always possible that the real ffmpeg devs will point out a problem with this line of reasoning but I doubt it. The outer loop is very simple conceptually - it's not doing much.

 

If this patch makes it, I'll have to actually install MB3 and try it out. (I'm currently a PLEX user who fundamentally dislikes their closed source model and have been lurking around watching the development of MB3 for a few months. It's a weird "hobby" of mine, I guess...)

Edited March 8, 2015 by FredipusRex

[FredipusRex 12]

Ok, I just read the multithreading code. It only affects the input side - it will read multiple input streams simultaneously and then place the packets on an in-memory queue. That queue is read only by the main thread (transcode loop).

 

We could potentially fill the memory queue while paused, which could cause a failure. This can be fixed with a paused check at the top of the while loop of the input_thread function.

 

Right after the while(1) { line, adding the following lines will fix it.

 

if (paused_start) {

av_usleep(1000); // Be more responsive to unpausing than the main thread

continue;

}

 

That will pause multithreaded input.

[jluce50 118]

Ok, I just read the multithreading code. It only affects the input side - it will read multiple input streams simultaneously and then place the packets on an in-memory queue. That queue is read only by the main thread (transcode loop).

 

 

I don't know if that's necessarily true in all cases. My (very limited) understanding is that certain libraries can take advantage of multithreading; e.g. libx264. As far as I know, it's not just on the input side. Anyway, the default for that codec is to use multiple threads if possible, but that can be changed via parameter. Take this with a grain of salt, though. Luke may be more familiar with whether multithreading codecs come into play for MB3. 

[FredipusRex 12]

Yeah, I'm not worried about the actual encoders (libx264, etc.) being multithreaded because we're controlling the data flow. This is a process of reading input stream data and outputing it - if we control that bit, how the encoders actually work is not important. Famous last words, I know...

[Luke 37090]

Yeah, I'm not worried about the actual encoders (libx264, etc.) being multithreaded because we're controlling the data flow. This is a process of reading input stream data and outputing it - if we control that bit, how the encoders actually work is not important. Famous last words, I know...

 

yea i think this could be fine. it sounds like multi-threaded decoding -> single threaded queue -> multi-threaded encoding. should be ok.

[Carlo 4330]

Yea, I think this should be OK also.  I just wasn't sure how it was implemented so I wanted to ask.  Good show.

 

Carlo

[jluce50 118]

yea i think this could be fine. it sounds like multi-threaded decoding -> single threaded queue -> multi-threaded encoding. should be ok.

 

So is the consensus that I should go ahead and add the pause to input_thread() as well or just leave that part as-is?

[Luke 37090]

To be honest I've only been reading and not looking at ffmpeg code too hard. Will have to defer to fredipus

[FredipusRex 12]

So is the consensus that I should go ahead and add the pause to input_thread() as well or just leave that part as-is?

 

Actually, we also need a way to deal with exit conditions (AVERROR_EXIT generated by 'q' key or received_nb_signals). The problem being that a simplistic pause will not free the input thread(s) when they get signaled, because the signaling occurs within libavutil/threadmessage.c.

 

Continuing with the pattern of leaving the lightest possible footprint on ffmpeg as a whole, I'd suggest dealing with this entirely inside ffmpeg.c - which, fortunately, is pretty easy.

 

In input_thread(), add the following code:

 

while (1) {

++    if (paused_start)

++    {

++        av_usleep(1000);        // Be more responsive to unpausing than the main thread

++    }

++

    AVPacket pkt;

 

Inside check_keyboard_interaction, we need to unpause if an error signal causes an abort:

 

--if (received_nb_signals)

--    return AVERROR_EXIT;

++if (received_nb_signals) {

++    if (paused_start)

++    {

++        paused_time += av_gettimerelative() - paused_start;

++        paused_start = 0;

++    }

++    return AVERROR_EXIT;

++}

 

If you want to move the pause/unpause code (which now occur in multiple spots inside check_keyboard_interaction), you can create little procedures to do it, e.g.

 

static void pause() {

    if (!paused_start)

        paused_start = av_gettime_relative();

}

 

static void unpause() {

    if (paused_start)

    {

        paused_time += av_gettimerelative() - paused_start;

        paused_start = 0;

    }

}

 

And use the procedures instead of the inline code, e.g.

 

if (received_nb_signals)

{

    unpause();

    return AVERROR_EXIT;

}

...

// Reserve 'u' for unpausing a paused transcode, but allow any key to// unpause for backward compatibilityif (key == 'u' || key != -1) unpause();if (key == 'p') pause();

That might be a bit cleaner.

Edited March 9, 2015 by FredipusRex

[jluce50 118]

Ah, good catch! Okay, I'll make these changes and hopefully get it submitted later today...