CMD %comspec% bug

[majstang]

I use FFmpeg to extact a snapshot/thumbnail (.jpg) out of 2500 .ts video files and encountered some suspicious stallings while batch processing all files at once. I do measure time between passing of .ts, FFmpeg jpg extraction until next file is passed.
Intermittently there are several examples where batch processing stalled between 2 minutes down to 0.5 seconds. The stallings always seem to happen when using %comspec% or if starting the FFmpeg processing via the StdOutToVar().

Code: Select all

RunWait %comspec% /c "%FFMpeg% -i "%RecDir%\%A_LoopField%" -frames:v 1 "%RecDir%\%NameNoExt%".jpg"
	  ; OR
	  commanline_makeJPG := StdOutToVar("cmd /c " FFMpeg " -i " """" RecDir "\" A_LoopField """" " -frames:v 1 " """" RecDir "\" NameNoExt """" ".jpg") ; ,,Hide
	  AddToBOF(A_ScriptDir . "\FFmpeg_StdOut.log", a_yyyy "-" a_mm "-" a_dd " " a_hour ":" a_min ":" a_sec "." A_MSec "-" commanline_makeJPG "`r`n`n")

- When cmd prompt stalls the script has already passed input filename and the command promt starts, but cmd is empty...just the blinking cursor there and do not respond at all...just waiting for something. The max wait time before cmd prompt does respond and loads the passed file to FFmpeg is 2 minutes. When cmd prompt does respond after the timeout FFmpeg loads ok and the snapshot is always generated successfully.
- The 2 minute timeout limit makes sure the stall durations are never ever longer than 2 minutes.
- These stallings does not follow a consistent pattern, they are completely random. Thumbnail creation for a certain file can stall and timeout in the first run, but works nicely in the next run (separate sessions).
- Im also logging the ffmpeg stdout and inspecting those for the files that stalled yields no clues upon why.

Some interesting things are exposed if using the AHK RunWait command with expressions.

Code: Select all

runparam := "ffmpeg.exe -i """ RecDir "\" A_LoopField """" " -frames:v 1 """ RecDir "\" NameNoExt ".jpg"""
RunWait, %runparam%, %FFmpegDir%

...not one single stall at all. Bug or user error? Interesting patterns in this case is:
- Majority 80% of all snapshots are created in 78 millisecs
- 200 jpg in 79 millisecs
- 40 jpg in 93 millisecs
-150 jpg in 94 millisecs
-15 jpg in 110 millisecs
- 3 jpg in 125 millisecs

The script used is something I did build myself borrowing lots of snippets from others and learning from the documentation and forum. To test it live my .ts files and FFmpeg is needed. I will glady provide them to anyone who are willing to help me with solving this problem.

Code: Select all

#NoEnv
SetBatchLines, -1 ; important for performance
AdjTime = 0
tray_icon := A_ScriptDir . "\magnify.ico"
Menu, Tray, Icon, %tray_icon%
RecDir := RegExReplace(A_ScriptDir, "\\vthumbsChecker")
;------------------------------------------------
Loop, % A_ScriptDir . "\ffmpeg.exe" 
  FFMpeg = %A_LoopFileShortPath% 
;------------------------------------------------
Gui, Font, s10 cBlack Bold,
Gui, Add, Text, x+10 yp+20 section h20, Loaded file in vthumbs.exe:
Gui, Font, 
Gui, Add, Edit, xs ys+20 h20 w500 vText,
Gui, Add, Tab2, xs ys+50 h460 w660 vMyTab +Theme -Background, Processed recordings|Successfully created thumbnails|No thumbnails created for these files
Gui, Font, s10 cBlack Bold,
GuiControl, Font, MyTab
Gui, Font, 
Gui, Tab, 1
Gui, Add, ListView, xs ys+73 h437 w759 cBlue Grid vLV1 gLV1gl, Nr|ProcessTime|Filename
Gui, Add, Button, xs+20 ys+530 h25 w50 vStart gStart, Start
Gui, Add, Button, xs+300 ys+530 h25 w50 gExit, Exit
Gui, Add, Button, xs+650 ys+530 h25 w80 vBut1 gLoadLog, Load logfile
Gui, Tab, 2
Gui, Add, ListView, xs ys+73 h437 w759 cGreen Grid vLV2 gLV2gl, Nr|ProcessTime|Filename
Gui, Add, Button, xs+20 ys+530 h25 w180 vDeleteJPGd hwndHCLS gDeleteJPG, Delete Created Thumbnails
Gui, Add, Button, xs+650 ys+530 h25 w80 vBut2 gLoadLog, Load logfile
Gui, Tab, 3
Gui, Add, ListView, xs ys+73 h437 w759 cRed Grid vLV3 gLV3gl, Nr|ProcessTime|Filename
Gui, Add, Button, xs+650 ys+530 h25 w80 vBut3 gLoadLog, Load logfile
Gui, Show, h600 w800
Return

Start:
Gui, Submit, NoHide
    RSfiles_TS := ""
	FileDelete, % A_ScriptDir . "\processedTS_thumbnail.log"
	FileDelete, % A_ScriptDir . "\success_JPGthumbnail.log"
	FileDelete, % A_ScriptDir . "\failureTS_NoThumbnail.log"
	FileDelete, % A_ScriptDir . "\FFmpeg_StdOut.log"
	Gui, Listview, LV1
    LV_Delete() 
	Gui, Listview, LV2
    LV_Delete()
    Gui, Listview, LV3
    LV_Delete()
	;---------
	Loop, Files, % RecDir "\*.ts", F
      RSfiles_TS .= (RSfiles_TS <> "" ? "`n" : "") A_LoopFileName	
	;---------
	Loop, Parse, RSfiles_TS, `n
	 {
	  ;msgbox % ShortPathName
	  ;runparam := "vthumbs.exe /q /h """ A_LoopField """" ; /q = quit each vthumbs.exe instance when done creating the thumb /h = hide UI 
	  GuiControl,, Text, % A_LoopField
	  Sleep, 50
	  SplitPath, A_LoopField,,,, NameNoExt,
	  ST := A_TickCount ; Start Time
	  ;RunWait, %runparam%, %RecDir%
	  ;--------------------
	  ;--No Stall------
	  ;--------------------
      runparam := "ffmpeg.exe -i """ RecDir "\" A_LoopField """" " -frames:v 1 """ RecDir "\" NameNoExt ".jpg"""
      ;msgbox % runparam
	  RunWait, %runparam%, %RecDir%
	  ;------------------
	  ; Gives Stallings
	  ;------------------
	  ;RunWait %comspec% /c "%FFMpeg% -i "%RecDir%\%A_LoopField%" -frames:v 1 "%RecDir%\%NameNoExt%".jpg"
	  ; enable below if hide cmd window
	  ;commanline_makeJPG := StdOutToVar("cmd /c " FFMpeg " -i " """" RecDir "\" A_LoopField """" " -frames:v 1 " """" RecDir "\" NameNoExt """" ".jpg") ; ,,Hide
	  ;AddToBOF(A_ScriptDir . "\FFmpeg_StdOut.log", a_yyyy "-" a_mm "-" a_dd " " a_hour ":" a_min ":" a_sec "." A_MSec "-" commanline_makeJPG "`r`n`n")
      ;----------
	  Timings := FormatCT((A_TickCount - ST) + AdjTime)
	  Gui, Listview, LV1
	  LV_Add("", a_index, Timings, A_LoopField)
	  LV_ModifyCol(3, "sortdesc")
	  LV_ModifyCol(1, "auto")
	  AddToBOF(A_ScriptDir . "\processedTS_thumbnail.log", a_yyyy "-" a_mm "-" a_dd " " a_hour ":" a_min ":" a_sec "." A_MSec "|" a_index "|" Timings "|" A_LoopField (a_index > 1 ? "`r`n" : ""))
	  
	  JPG := RecDir "\" NameNoExt ".jpg"
	  If (FileExist(JPG)) {
	    Gui, Listview, LV2
		LV_Add("", a_index, Timings, JPG)
		LV_ModifyCol(3, "sortdesc")
		LV_ModifyCol(1, "auto")
		AddToBOF(A_ScriptDir . "\success_JPGthumbnail.log", a_yyyy "-" a_mm "-" a_dd " " a_hour ":" a_min ":" a_sec "." A_MSec "|" a_index "|" Timings "|" JPG (a_index > 1 ? "`r`n" : ""))
	  }
      Else {
	    Gui, Listview, LV3
		LV_Add("", a_index, Timings, A_LoopField)
		LV_ModifyCol(3, "sortdesc")
		LV_ModifyCol(1, "auto")
		AddToBOF(A_ScriptDir . "\failureTS_NoThumbnail.log", a_yyyy "-" a_mm "-" a_dd " " a_hour ":" a_min ":" a_sec "." A_MSec "|" a_index "|" Timings "|" A_LoopField (a_index > 1 ? "`r`n" : ""))
	  }
	 }
    ;---------
	thumbsList := ""
	Loop, Files, % RecDir "\*.jpg", F
		thumbsList .= StrReplace((thumbsList <> "" ? "`n" : "")A_LoopFileName, ".jpg", ".ts",, -1) ; Change from .jpg to .ts to be abled to match filenames 
    ;msgbox % "thumbsList=`n" thumbsList "`n`nRSfiles=`n" RSfiles_TS 
    ;---------
	;Msgbox % "RSfiles which didn't get a thumbnail.JPG created:`n" result1
    GuiControl, ChooseString, MyTab, Successfully created thumbnails
	;GuiControl, Show, %HCLS%
	;PostMessage, 0x00F5, 0, 0, , ahk_id %HCLS% ; BM_CLICK ;20151109
	;GuiControl, Focus, %HCLS%
	msgbox  Vthumbs thumbnail processing for all files are now done. All processed files, files where thumbnails failed and successfully created thumbnails are saved in three separate logfiles.`nprocessedTS_thumbnail.log`nfailureTS_NoThumbnail.log`nsuccess_JPGthumbnail.log
Return

DeleteJPG:
Gui, Submit, NoHide
	MsgBox, 4, , Do you want to Delete (Recycle Bin) the thumbnails just created? (Press YES or NO)
    IfMsgBox, Yes
	{
	 If (thumbsList = "") {
	   Loop, Files, % RecDir "\*.jpg", F
	      thumbsList .= (thumbsList <> "" ? "`n" : "")A_LoopFileName
     }
	 Loop, Parse, thumbsList, `n
      {
	   SplitPath, A_LoopField, OutFileName, OutDir, OutExtension, OutNameNoExt, OutDrive
	   FileRecycle, % RecDir "\" OutNameNoExt ".jpg"
	   ;FileDelete, % RecDir "\" OutNameNoExt ".jpg"
	   Gui, Listview, LV2
	   LV_Delete()
      }
	}
	IfMsgBox No
      return
	thumbsList := ""
Return

LoadLog:
LOG_File := ""
FileSelectFile, LogFile,, % A_ScriptDir, Load Logfile, Log Documents (*.log)
If (A_GuiControl = "But1") {
  Gui, Listview, LV1
  LV_Delete()
} 
Else If (A_GuiControl = "But2") {
  Gui, Listview, LV2
  LV_Delete()
} 
Else If (A_GuiControl = "But3") {
  Gui, Listview, LV3
  LV_Delete()
} 
FileRead, LOG_File, *P65001 %LogFile%       ;Reads content of LOG_File (UTF-8)
GuiControl, -Redraw, LV
Loop, Parse, LOG_File, `n
{
  If A_LoopField=
    Continue
  Split := StrSplit(A_LoopField, "|")
  If (A_GuiControl = "But1")
    Gui, Listview, LV1
  Else If (A_GuiControl = "But2")
    Gui, Listview, LV2
  Else If (A_GuiControl = "But3")
    Gui, Listview, LV3
  LV_Add("", Split.2, Split.3, Split.4)
}  
LV_ModifyCol(3, "sortdesc")
LV_ModifyCol(1, "auto")
GuiControl, +Redraw, LV
Return

Exit:
GuiEscape:
GuiClose:
ExitApp

LV1gl:
if (A_GuiEvent = "DoubleClick") {
  LV_GetText(Filename, A_EventInfo, 3)
  Filename := RTrim(Filename, "`r`n")
  SplitPath, Filename,,, Extension,,
  If (Extension = "jpg") {
    Run %Filename%,, UseErrorLevel
    If ErrorLevel
      MsgBox Could not open "%FileName%".
  }
  If (Extension = "ts") {
    Run %RecDir%\%Filename%,, UseErrorLevel
    If ErrorLevel
      MsgBox Could not open "%FileName%".
  }
}
If (A_GuiEvent = "R") ; DoubleRightClick
{
  LV_GetText(Filename, A_EventInfo, 3)
  Clipboard := Filename
  ToolTip, % Clipboard . "`nwas copied to the clipboard!"
  SetTimer, ToolTipTimeout, -2000
  Return
}
Return

LV2gl:
if (A_GuiEvent = "DoubleClick") {
  LV_GetText(Filename, A_EventInfo, 3)
  Filename := RTrim(Filename, "`r`n")
  SplitPath, Filename,,, Extension,,
  If (Extension = "jpg") {
    Run %Filename%,, UseErrorLevel
    If ErrorLevel
      MsgBox Could not open "%FileName%".
  }
  If (Extension = "ts") {
    Run %RecDir%\%Filename%,, UseErrorLevel
    If ErrorLevel
      MsgBox Could not open "%FileName%".
  }
}
If (A_GuiEvent = "R")  ; DoubleRightClick
{
  LV_GetText(Filename, A_EventInfo, 3)
  Clipboard := Filename
  ToolTip, % Clipboard . "`nwas copied to the clipboard!"
  SetTimer, ToolTipTimeout, -2000
  Return
}
Return

LV3gl:
if (A_GuiEvent = "DoubleClick") {
  LV_GetText(Filename, A_EventInfo, 3)
  Filename := RTrim(Filename, "`r`n")
  SplitPath, Filename,,, Extension,,
  If (Extension = "jpg") {
    Run %Filename%,, UseErrorLevel
    If ErrorLevel
      MsgBox Could not open "%FileName%".
  }
  If (Extension = "ts") {
    Run %RecDir%\%Filename%,, UseErrorLevel
    If ErrorLevel
      MsgBox Could not open "%FileName%".
  }
}
If (A_GuiEvent = "R")  ; DoubleRightClick
{
  LV_GetText(Filename, A_EventInfo, 3)
  Clipboard := Filename
  ToolTip, % Clipboard . "`nwas copied to the clipboard!"
  SetTimer, ToolTipTimeout, -2000
  Return
}
Return

ToolTipTimeout:
ToolTip
Return
;----------------------------------------------------------------------
;FUNCTIONS
;----------------------------------------------------------------------
FormatCT(ms)  ;  Formats milliseconds into 00:00:00:000 (last three digits are milliseconds)
{
	StringRight , mil , ms , 3
	StringTrimRight , sec , ms , 3
	min := Floor(sec/60)
	sec := sec-(min*60)
	hrs := Floor(min/60)
	min := min-(hrs*60)
	While StrLen(sec) <> 2
		sec := "0" . sec
	While StrLen(mil) <> 3
		mil := "0" . mil
	While StrLen(min) <> 2
		min := "0" . min
	While StrLen(hrs) <> 2
		hrs := "0" . hrs 
	return , hrs . ":" . min . ":" . sec . ":" . mil
}
;------------reverse logging function------------------------------------------------------------------------------
AddToBOF(FileName, String) { ; AddToBeginOfFile
   If (File := FileOpen(FileName, "rw", "UTF-8-RAW")) {
      Content := File.Read()
      File.Pos := 0
      File.Write(String . Content)
      File.Close()
      Return True
   }
   Return False
}
;------------------------------------------------------------------------------------------
StdOutToVar( sCmd ) { ;  GAHK32 ; Modified Version : SKAN 05-Jul-2013  http://goo.gl/j8XJXY                             
  Static StrGet := "StrGet"     ; Original Author  : Sean 20-Feb-2007  http://goo.gl/mxCdn  
   
  DllCall( "CreatePipe", UIntP,hPipeRead, UIntP,hPipeWrite, UInt,0, UInt,0 )
  DllCall( "SetHandleInformation", UInt,hPipeWrite, UInt,1, UInt,1 )

  VarSetCapacity( STARTUPINFO, 68, 0  )      ; STARTUPINFO          ;  http://goo.gl/fZf24
  NumPut( 68,         STARTUPINFO,  0 )      ; cbSize
  NumPut( 0x100,      STARTUPINFO, 44 )      ; dwFlags    =>  STARTF_USESTDHANDLES = 0x100 
  NumPut( hPipeWrite, STARTUPINFO, 60 )      ; hStdOutput
  NumPut( hPipeWrite, STARTUPINFO, 64 )      ; hStdError

  VarSetCapacity( PROCESS_INFORMATION, 16 )  ; PROCESS_INFORMATION  ;  http://goo.gl/b9BaI      
  
  If ! DllCall( "CreateProcess", UInt,0, UInt,&sCmd, UInt,0, UInt,0 ;  http://goo.gl/USC5a
              , UInt,1, UInt,0x08000000, UInt,0, UInt,0
              , UInt,&STARTUPINFO, UInt,&PROCESS_INFORMATION ) 
   Return "" 
   , DllCall( "CloseHandle", UInt,hPipeWrite ) 
   , DllCall( "CloseHandle", UInt,hPipeRead )
   , DllCall( "SetLastError", Int,-1 )     

  hProcess := NumGet( PROCESS_INFORMATION, 0 )                 
  hThread  := NumGet( PROCESS_INFORMATION, 4 )                      

  DllCall( "CloseHandle", UInt,hPipeWrite )

  AIC := ( SubStr( A_AhkVersion, 1, 3 ) = "1.0" )                   ;  A_IsClassic 
  VarSetCapacity( Buffer, 4096, 0 ), nSz := 0 
  
  While DllCall( "ReadFile", UInt,hPipeRead, UInt,&Buffer, UInt,4094, UIntP,nSz, UInt,0 )
   sOutput .= ( AIC && NumPut( 0, Buffer, nSz, "UChar" ) && VarSetCapacity( Buffer,-1 ) ) 
              ? Buffer : %StrGet%( &Buffer, nSz, "CP850" )
 
  DllCall( "GetExitCodeProcess", UInt,hProcess, UIntP,ExitCode )
  DllCall( "CloseHandle", UInt,hProcess  )
  DllCall( "CloseHandle", UInt,hThread   )
  DllCall( "CloseHandle", UInt,hPipeRead )

Return sOutput,  DllCall( "SetLastError", UInt,ExitCode )
}

[BoBo]

Not my cup of tea, but how's it to set fixed process priorities so your benchmark isn't endangered of being interfered by other concurrent processes?

[majstang]

Hello BoBo,
Could you elaborate with some code samples? I thought each iteration is a single thread and do not see how interference by other concurrent processes could happen. It is not like if the command prompt goes into mark mode or anything (when clicking the prompt all StdOutput is suspended waiting infinite for user input which can be disabled by unchecking the Quick edit mode). Also when running a batch session I do make sure nothing else is running that can interfer. If using the second No-stall-method which also opens a command prompt howcome there is no strange suspensions and suspention timeouts there?

[majstang]

Looks like i managed to figure this one out on my own. FFmpeg does natively creates a new console window. If then calling FFmpeg by "comspec" or "cmd" should logically create two console windows (closes too fast to see with the naked eye...the entire processing time is a few millisecs) which sometimes clashes causing the mysterious stallings. That is the only likely explanation as far as I can see it. Any disagreeing opinions?