Reading % completion from stderr output

[dlflannery]

Hi Erik,

I'm the developer of VideoReDo-Autoprocessor (VAP), which automates processing with VideoReDo and ComSkip:

http://www.videoredo.net/msgBoard/showp ... ostcount=1

(Sorry, it won't let me use url tags.)
I'm modifying my program to provide a progress bar representing comskip % completion in the GUI.
My understanding is this info is available only from the stderr output, correct? Thus I am parsing the stderr output for the '%' character and parsing out the % completion number just preceding it. This seems to work well.

When testing with a donor version of Comskip, 0.81.028, the progess percentage reported via stderr actually goes up for a while then jumps back to zero and climbs back up to (near) 100%. That is what stderr is reporting, not a bug in my code. Is this expected behavior for comskip?

Is there a simpler way to get % completion other than parsing it out of stderr?

Also, VAP runs comskip.exe by launching VBScript running in Windows scripting. One reason for this is so I can hide the black command window. I had been using the shell object's "Run" command up til now, following a hint you provided via Marvin-Miller. (Thanks.)
However, I've been unable to find a way to redirect the stderr from Comskip when I run it directly using the "Run" command. To make it work I have to launch a .cmd script with the "Run" command and have the command script run comskip and redirect it's stderr into a file, which I read frequently from the VAP program to parse out the % completion. As it said, it works fine -- but it's not elegant. If you have any suggestions for a cleaner way to do this, they would be appreciated. I tried using the scripting shell's "exec" command, which gives access to stderr, but it doesn't work, and it doesn't hide the command window either.

Thanks

[erik]

Just a quick answer to the % sequence.
I noticed that on certain files the duration info is read incorrectly.
I will have a look.

W.r.t other ways to get the progres, the only way is to add an additional output file where I write the progress or I add it to the log file

What is your preference?

[dlflannery]

Probably due to my inexperience with Comskip, I don't know what the "big file" is. Is that the .edl file?
EDIT: Sorry, when I first read your previous post, I thought it said "big file" instead of "log file".

One issue I have with redirecting stderr to a file (i.e., the way I'm doing it now) is that I have to use kluge code just to read the file. VAP is written in C# and the usual way to read a file is File.ReadAllText(<filepath>). However this throws an access-denied exception because the file is in use by another process (Comskip of course). My workaround is to use File.Copy() to copy the file to another temp file, then read that file. (Why this works but not the File.ReadAllText() function is somewhat puzzling.) Anyway this process, plus parsing the file for % completion is done about every two seconds by VAP while Comskip is runniing. It's not elegant but it does seem to work well.

It would be nice if any other approach could eliminate the file-in-use issue but that may be hard to do, since ...... the file is in use! VAP uses other VBScripts to run VideoReDo's COM objects (for VRD processing). VAP can read the stdout from these scripts (produced by wscript.writeline) to track progress and get other info while the COM processes are executing. However, I haven't figured out a way to capture stderr coming out of Comskip when it is being run by the shell object's "Run" command.

I'm not sure how much of a modification is justified for this, since I already have something that seems to work pretty well, but thanks for your attention.

[dlflannery]

Update: My desire for any mod to comskip to faciliate getting % completion is very small now. I've figured out how to redirect stderr from the comskip process directly into my C# code, which eliminates the need to use any temp files. Thanks anyway!

[erik]

Good to hear

[dlflannery]

The 81_031 donators version is returning all 0% completion in STDERR throughout its runs, at least on WTV Mpeg2 files.

[erik]

I found the problem, will be corrected in build 0.81.032 to be released soon.

[dlflannery]

Thanks!

[dlflannery]

Hmmm.... A quirk is back in 80_32 that I thought had been fixed in 80_31:

On a 3.3 GB, 1 hr, WTV H.264 file, the % progress reported in stderr goes up to about 75% then drops back to 0% and climbs up to 100% at finish.

[KryptoNyte]

Comskip/VideoRedo/VAP progress bar, Results:

.mpg (mpeg2) SageTV
*VAP Progress bar hits about 4%, resets to zero, restarts and is smooth from 0% to 100%
Commercial detection is thorough and accurate.
Comskip speed is very good.

.wtv (mpeg2) Win7 Media Center
VAP Progress bar hits about 10%, resets to zero, restarts and is smooth from 0% to 100%
Commercial detection is thorough and accurate.
Comskip speed is very good.

.ts (h264) SageTV
VAP Progress bar hits about 4%, resets to zero, restarts and is smooth from 0% to 100%
Commercial detection is thorough and **accurate
Comskip speed is acceptable.

General note:
Comskip is set to use all (4) of my true cores, however overall processor usage never exceeds 45% with the above files.


*I have seen one straight up mpeg2 file process with absolutely no glitch in the progress bar, so it is file dependent for some reason.

**This is important for this HD-PVR/SageTV generated h264.ts file, as this is the first time (since October 2011) that the commercial cut locations were not shifted by about 2 minutes, or more recently, 6 seconds, from the correct timeline locations.

[erik]

Well, what you do see wit the progress bar is correct, at least, that is how it is implemented.
Comskip searches for the logo and then restarts scanning.
I did not yet bother to implemented something correct this.

W.r.t accuracy that is good news.

If you need more usage of your cores you can try to set
thread_count=6 or higher
The thread switching causes some latency causing lower utilisation

[dlflannery]

Setting thread_count=6 cut the processing time down from 21 min to 13 min, a major imrovement, although strangely overall CPU usage ran about the same, around 23%. Still only 4 of the 8 hyperthreads were active, although a 5th one occasionally showed some activity.

However there is a more disturbing result: The .vprj files produced (using the identical input file and no changes to the .ini file other than thread_count) were significantly different. There were 2 cuts defined in one but 3 cuts defined in the other, and many of the marker positions differed although perhaps only slightly.

The 2 major cuts were practically identical (within a frame or two) but the 6-thread case failed to cut a 30-second commercial at about the middle (34:06:10 to 34:36:08). Is this explainable as an artifact of using more threads?

I also noticed that the % progress values did not cycle twice on the 6-thread case, or maybe the first cycle was so small I missed it (?).

I don't see a way to attach files so I'm including the two .vprj files in this post:

First the output using no thread_count line in the .ini file:

Code: Select all

<Version>2
<Filename>C:\VAP\Monitor\Beauty and the Nerd_RTL 5_2010_08_15_19_55_00.wtv
<MPEG Stream Type>4
<Cut>9316000000:13156000000
<Cut>20464000000:20763200000
<Cut>34274000000:38921600000
<SceneMarker 0>8933200000
<SceneMarker 1>9315200000
<SceneMarker 2>9567600000
<SceneMarker 3>9870000000
<SceneMarker 4>10122400000
<SceneMarker 5>10324800000
<SceneMarker 6>10477200000
<SceneMarker 7>10879600000
<SceneMarker 8>11181600000
<SceneMarker 9>11484000000
<SceneMarker 10>11686400000
<SceneMarker 11>11788800000
<SceneMarker 12>11941200000
<SceneMarker 13>12093600000
<SceneMarker 14>12296000000
<SceneMarker 15>12448400000
<SceneMarker 16>12650800000
<SceneMarker 17>13003200000
<SceneMarker 18>13155600000
<SceneMarker 19>20463200000
<SceneMarker 20>20541600000
<SceneMarker 21>20762800000
<SceneMarker 22>34273400000
<SceneMarker 23>34475800000
<SceneMarker 24>34778200000
<SceneMarker 25>35080600000
<SceneMarker 26>35283000000
<SceneMarker 27>35485400000
<SceneMarker 28>35787800000
<SceneMarker 29>35890200000
<SceneMarker 30>36042600000
<SceneMarker 31>36138200000
<SceneMarker 32>36246200000
<SceneMarker 33>36546400000
<SceneMarker 34>36648800000
<SceneMarker 35>36828400000
<SceneMarker 36>36851200000
<SceneMarker 37>37053600000
<SceneMarker 38>37106000000
<SceneMarker 39>37308400000
<SceneMarker 40>37460800000
<SceneMarker 41>37763200000
<SceneMarker 42>37815600000
<SceneMarker 43>38062400000
<SceneMarker 44>38921600000

Now the output using thread_count-6 :

Code: Select all

<Version>2
<Filename>C:\VAP\Monitor\Beauty and the Nerd_RTL 5_2010_08_15_19_55_00.wtv
<MPEG Stream Type>4
<Cut>9316000000:13156000000
<Cut>34274000000:38920800000
<SceneMarker 0>8933200000
<SceneMarker 1>9315200000
<SceneMarker 2>9567600000
<SceneMarker 3>9870000000
<SceneMarker 4>10122400000
<SceneMarker 5>10324800000
<SceneMarker 6>10477200000
<SceneMarker 7>10879600000
<SceneMarker 8>11181600000
<SceneMarker 9>11484000000
<SceneMarker 10>11686400000
<SceneMarker 11>11788800000
<SceneMarker 12>11941200000
<SceneMarker 13>12093600000
<SceneMarker 14>12296000000
<SceneMarker 15>12448400000
<SceneMarker 16>12650800000
<SceneMarker 17>13003200000
<SceneMarker 18>13155600000
<SceneMarker 19>20762800000
<SceneMarker 20>34273400000
<SceneMarker 21>34475800000
<SceneMarker 22>34778200000
<SceneMarker 23>35080600000
<SceneMarker 24>35283000000
<SceneMarker 25>35485400000
<SceneMarker 26>35787800000
<SceneMarker 27>35890200000
<SceneMarker 28>36042600000
<SceneMarker 29>36138200000
<SceneMarker 30>36246200000
<SceneMarker 31>36546400000
<SceneMarker 32>36648800000
<SceneMarker 33>36828400000
<SceneMarker 34>36851200000
<SceneMarker 35>37053600000
<SceneMarker 36>37106000000
<SceneMarker 37>37308400000
<SceneMarker 38>37460800000
<SceneMarker 39>37763200000
<SceneMarker 40>37815600000
<SceneMarker 41>38062400000
<SceneMarker 42>38920800000

[erik]

The second pass may have reused the logo file and therfore NOT reset to begin after finding the logo
To ensure identical conditions you have to delete the logo file or set in comskip.ini not to keep it.

[dlflannery]

The second pass may have reused the logo file and therfore NOT reset to begin after finding the logo
To ensure identical conditions you have to delete the logo file or set in comskip.ini not to keep it.

Would that explain getting different cut results for the identical input file? (I can see where it would explain shorter processing time, of course.)

[erik]

Well, it should not be but there always can be an error in comskip.
There may be a parameters set "on the edge" so even a minute rounding difference can give a different result.
Can you follow the " how to ask for help" post and send me the info so I can have a look?