Hello,
Is there a way to get proper progress reporting for a multi frame htoa task in houdini?
The progress bar jumps around as the tasks progresses. I’m assuming it’s grabbing the standard out from Houdini.py.
self.AddStdoutHandlerCallback( ".*?(\d+)% done.*" ).HandleCallback += self.HandleStdoutFrameProgress
and not reporting the progress as a percentage of frames completed for the task?
Thanks,
-Jake
That’s exactly what it’s doing. That’s all the information we’ve got to use to drive that progress. Ideally that XX% done output would be for all frames that will be rendered versus just the one frame its rendering now.
If there are lines that htoa jobs print that represent progress across the frames it wouldn’t be too complicated to tweak Houdini.py to use that instead.
You’d comment out the AddStdoutHandlerCallback that’s using the jumpy progress and insert your own, hooked into HandleStdoutFrameProgress as before.
Hi Justin,
Thanks for confirming. The lines for frame progress during a multi frame task aren’t the most ideal, but should be able to make it work:
2023-07-20 01:07:51: 0: STDOUT: 00:00:11 775MB | render done in 0:10.034
2023-07-20 01:07:51: 0: STDOUT: 00:00:11 775MB | [driver_exr] writing file `T:/project/vfx/YTA/YTA_0090/lighting/work/houdini/render/deadlinetest/spherebty/v002/YTA_0090_deadlinetest_spherebty_v002.1003.exr'
2023-07-20 01:07:54: 0: STDOUT: 00:00:13 603MB | render done
Oh yeah that’s not going to be a tidy one-liner.
Off the cuff you could count the number of ‘render done’ hits you’ve seen and divide them by the number of frames in the task.
I’m not finding a nice way to say ‘give me the frames for this task’ but self.GetStartFrame and self.GetEndFrame in Houdini.py will be good enough.
Thanks for the suggestions Justin. I’ll give it a go.
1 Like
Hi Justin,
I have something that’s working well at the moment.
However, I’ve run into an issue where the next task momentarily pops to 100% before it resumes normal progress calculation starting from 0%.
Having a hard time working out where this is coming from - wondering if anyone else has had a similar issue?
I think it seems to happen on htoa jobs even with the unmodified Houdini.py from install.
In that case I’d bet one of the other standard output handlers is getting triggered and updating the progress.
You could enable debug logging in the Monitor under Tools → Configure Plugins → Houdini to get a better idea of what the plugin is doing.
Just be sure to turn it back off after you’re done, it’s only helpful for plugin troubleshooting and doesn’t help with render troubleshooting.
The debug logging is very helpful.
I can see where the arnold regex is getting triggered during the render process…it seems to be in the right spot and is not triggered at the head of a job.
It’s also worth noting that the subsequent frame doesn’t always start at 100%. Sometimes it’s at 0%.
It’s almost as if that progress value is sometimes somehow left over from the previous render process and not getting cleaned up properly?
The tasks do not exhibit this behavior if I have “Reload Plugin Between Tasks” checked ON.
I’ve attached a debug log from one of the tasks that did exhibit the issue of starting at 100% and then dropping to 0% when the render process began.
Thanks,
-Jake
Job_ProgressIssue.zip (12.3 KB)
If the solution to this is that we should have “Reload Plugin Between Tasks” on by default, we can do so.
Is there a big benefit to having this checked OFF? Aside from the actual plugin loadtime(seems to be about 5 seconds), is there any scene relevant data that can also carry through by not having the plugin reload in between tasks?
Thanks,
-Jake
Hey Jake! The biggest problem is that Houdini and the scenes would be reloaded. If the added gap is only 5 seconds, that should be fine. I’m rather surprised it’s not longer.
You’ll also need to avoid that if for some reason you’re performing a simulation and not writing out the data. Every tasks Houdini would re-sim the data.
This all said, the magic that handles progress in “[repo]\plugins\Houdini\Houdini.py” is this here:
def HandleStdoutFrameProgress(self):
if self.ropType in ("ifd", "rop_ifd"):
frameCount = self.GetEndFrame() - self.GetStartFrame() + 1
if frameCount != 0:
completedFrameProgress = float(self.completedFrames) * 100.0
currentFrameProgress = float(self.GetRegexMatch(1))
overallProgress = (completedFrameProgress + currentFrameProgress) / float(frameCount)
self.SetProgress(overallProgress)
self.SetStatusMessage( "Progress: " + str(overallProgress) + " %" )
elif self.ropType in ("arnold", "geometry", "rop_geometry", "wedge", "Octane_ROP", "ris::22"):
overallProgress = float(self.GetRegexMatch(1))
self.SetProgress(overallProgress)
self.SetStatusMessage( "Progress: " + str(overallProgress) + " %" )
That’s it. A few places we’re setting progress to 0 and 100 and so our bug is going to be in here somewhere or other. I think you know this (and what’s below) but I’m just sort of documenting as I’m thinking here…
The four RegExs that handle that for the standard output handlers are these four here:
".*ALF_PROGRESS ([0-9]+)%.*"
".*?(\d+)% done.*"
"\[render progress\] ---[ ]+(\d+) percent"
"RMAN_PROGRESS *([0-9]+)%"
The second one is what should trip, and you’re right. It absolutely is still correct (at least according to VSCode’s regex matching :P)
Considering that, I’m thinking that because our filtering code doesn’t have a fall-through, we’re just throwing it out. Which frankly isn’t very helpful.
Can make a backup of “[repo]\plugins\Houdini\Houdini.py” and plunk this function in the old one’s place and see if it magically works:
def HandleStdoutFrameProgress(self):
if self.ropType in ("ifd", "rop_ifd"):
frameCount = self.GetEndFrame() - self.GetStartFrame() + 1
if frameCount != 0:
completedFrameProgress = float(self.completedFrames) * 100.0
currentFrameProgress = float(self.GetRegexMatch(1))
overallProgress = (completedFrameProgress + currentFrameProgress) / float(frameCount)
self.SetProgress(overallProgress)
self.SetStatusMessage( "Progress: " + str(overallProgress) + " %" )
elif self.ropType in ("arnold", "geometry", "rop_geometry", "wedge", "Octane_ROP", "ris::22"):
overallProgress = float(self.GetRegexMatch(1))
self.SetProgress(overallProgress)
self.SetStatusMessage( "Progress: " + str(overallProgress) + " %" )
else:
overallProgress = float(self.GetRegexMatch(1))
self.LogWarning( "Unknown ropType of '%s' for progress reporting. Assuming progress is %s %" % (self.ropType, str(overallProgress)) )
self.SetProgress(overallProgress)
self.SetStatusMessage( "Progress: " + str(overallProgress) + " %" )
It should now throw a warning and tell me what the ropType should be.
Thanks!
Hi Edwin,
Thanks for looking into this!
I added this additional line to the “HandleStdoutFrameProgress” function. Unfortunately, it’s still exhibiting the same behavior and not logging anything from the else statement ("Unknown ropType…).
This is a tough one. I’ve gone through the plugin, and for debug purposes, played around with setting self.SetProgress(0) in various functions, hoping that I could get it to pick that up on next task. But still no luck.
-Jake
Hello Jake
The first thing I do when I am testing my changes (it might have been suggested in the trailing responses) is to reload the plugin between tasks if you are making changes to [Repo]/plugins/Houdini/Houdini.py Do it form the job: Right menu> Modify Job Properties> General> Reload Plugin between tasks.
If that does not work, check if you have got something in [Repo]/custom/Houdini/ this takes precedence over the main folder.
Hi Zain,
Thanks for the suggestions. Unfortunately, the progress issue doesn’t happen when “Reload Plugin between tasks” is enabled. I can confirm that the changes that I am making to the plugin are picking up, because I can see some of my debug logging statements update as I make tweaks.
Well, this is pretty strange. We’ve seen a problem in the Command Line plugin too recently where for reasons we haven’t figured out yet the reporting doesn’t work at all…
If you’d be willing to do a little more digging, I’d be curious what would happen if you added another AddStdoutHandler() to the initalization code that caught everything and sent it to HandleStdoutFrameProgress(). You’d need to make sure it was the last handler added because Deadline stops processing output after the first match it finds.
If you don’t have time I can maybe take a look in a week or two…
Hi Edwin,
Thanks for the reply. Still have yet to circle back around and give this a shot.
Would be great to know what happens if you are able to test.
-Jake
This has been pretty low on my priority list but I’m able to reproduce progress problems again with the Command Line plugin using python3 -u progress.py so I don’t think this is specific to Houdini… It may be specific to Python/Hython but I’m skeptical about that.
Still needs more investigating…
Thanks for the update Edwin.
Have put aside attemps to fix this on our side as well.
-Jake
1 Like