From: Hugh Macdonald <hughm@(email surpressed)>
Subject: Logging progress inside a command
   Date: Mon, 23 Oct 2006 06:24:58 -0400

Hi all,

What am I missing here?

Thanks!

--
Hugh Macdonald
Rainmaker UK

Hugh Macdonald wrote:

[posted to rush.general]

Hi all,

I'm relatively new to Rush, having helped evaluate it for a previous company (we ended up deciding to stick with Alfred for the time being, which we had a lot of code based around), and am now working at a company that has recently started using Rush.

I've looked through the docs, and scanned the archives of the newsgroup for the answer to this question, but nobody seems to have brought it up, so I'm going to assume that I'm being a muppet and am missing something obvious. If you could tell me what I'm missing (in the nicest possible way), I'd be grateful.

At the moment, Rush will only give a Done % as each box finishes, but I'd like it to be able to pick up when, for example, a box is 50% done. Something that is easily parsable from the Shake output...

	Irush doesn't try to parse the continuous output of the renderers,
	though I suppose it could.

	I've seen a few requests for this before, and I might try to entertain
	adding it as a feature to rush if a see a clean technical path to
	implement it that doesn't suffer from scaling problems.

	Mainly it's an issue of scalability.. eg. if you start a rush job
	and it jumps on 50 machines, irush would have to parse the logs
	for realtime output of all 50 machines to update the report. Or worse,
	if there's 300 machines that start working on the job.

	Also, rush supports a lot of renderers.. many don't show percent
	completion messages, so it wouldn't be universally deployable.
	And finally some renders (mental ray) goes through the zero-to-100
	percent progress potentially several times, depending on how many
	passes it has.

	The current way to monitor progress in real time is to get an idea
	of the average time it takes frames to render (see the 'ELAPSED'
	times in the 'Frames' report, or the 'average render time' in the
	'Frames Info' report), and then put the Frames button on 'repeat'
	(Hit "REP", then hit "Frames"), and then monitor the ELAPSED times
	for the busy frames to see how fast things are going.

	Or, just keep the 'Frame Info' or 'Jobs' report on 'repeat' to
	keep an eye on one or several jobs at a time.


--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Fax: (Tel# suppressed)
Cel: (Tel# suppressed)

Thanks Greg - that does kinda make sense....

To answer a couple of your points....

Greg Ercolano wrote:

    Also, rush supports a lot of renderers.. many don't show percent
    completion messages, so it wouldn't be universally deployable.
    And finally some renders (mental ray) goes through the zero-to-100
    percent progress potentially several times, depending on how many
    passes it has.

    The current way to monitor progress in real time is to get an idea
    of the average time it takes frames to render (see the 'ELAPSED'
    times in the 'Frames' report, or the 'average render time' in the
    'Frames Info' report), and then put the Frames button on 'repeat'
    (Hit "REP", then hit "Frames"), and then monitor the ELAPSED times
    for the busy frames to see how fast things are going.

--
Hugh Macdonald
Rainmaker UK

I have done exactly that in the past.  The biggest problem with implementing 
something like this is you have to open a pseudo tty (pty) and run the 
program attached to the pty.  Some programs behave differently if they are 
attached to a tty.  Also another issue is there is some overhead with the 
"rush -notes" command.  When 100's of cpus are all calling "rush -notes" you 
do feel it on the job server.

> My thinking here would be that Rush would require some kind of wrapper
> around the application to convert the application's progress reports
> into something that makes more sense to Rush. Pretty much in the same
> way that Alfred does it. I work mainly with Shake, and if I've, say, got
> 5 frames rendering on each render machine, the wrapper script would
> translate Shake saying that frame 1/5 is 50% complete to telling rush
> that the whole box is 10% complete. Alfred ignores any output from the
> application except for lines that look something like "ALF_PROGRESS 23%"
>

Hugh Macdonald wrote:
> My thinking here would be that Rush would require some kind of wrapper
> around the application to convert the application's progress reports
> into something that makes more sense to Rush. Pretty much in the same
> way that Alfred does it.

	I'm not sure what alfred does, but my approach would probably
	be to implement the log parsing in irush.

	Possibly irush would need to call the submit script in order
	to convert the log output into percentage info that irush
	can show, so that the parsing logic can be modified in the
	submit script, should it change from version-to-version of
	the renderer.

	Thing is, managing the realtime logs of potentially tens or
	hundreds of files in progress, and piping their data through
	such a parser is not trivial technically across all platforms
	at the workstation.

	It can be done, but there's a lot of bending over backwards
	to accumulate this info, and it would add a bit of traffic
	to the machine doing the accumulation.

	The other route would be to have the remote rush daemons
	parse the logs for just the processors they're working on,
	and make that data available the daemon protocol back to irush,
	so that irush can 'poll' for the info.

	The latter is probably the best approach, but would involve
	irush having to contact each machine busy rendering to get
	the accumulated percentage info. Might be possible, but kinda
	ugly, because currently rush daemons don't look at the log data,
	it just redirects it to the server, leaving the daemon available
	to do scheduling and manage other tasks.

> You could, potentially, write wrapper scripts for the more common
> renderers that Rush supports, and if users wanted to get progress
> information for others, I'm sure they'd be capable of writing a small
> wrapper script.

	If sufficiently motivated, you can certainly use the info from
	'rush -lf' to write a dedicated app to monitor the logs of busy
	frames and show the percent completion data.

	Such a dedicated app shouldn't be too bad under unix using the
	tail command.. a bit harder under windows because there is no
	tail command in windows (unless you have the SFU or cygwin stuff).
	You can do pipes in WIN32, but it's a bit more complicated..
	I believe Active Perl for windows gives you access to that API.

> Your example of Mental Ray, again, would fall into the same camp as
> Shake - the wrapper script could (I don't know MR, so I don't know how
> easy this would be) know how many passes are coming out, and so turn
> each 0-100% progress into a subset of the whole progress

	Determining the number of passes is the issue.. this means
	diving into the scene files to determine this.. not somewhere
	I want to go, as the scene files are often in proprietary
	binary format, and are very hard to parse even if ascii.
	And with the constant changes in the renderers, it would
	be very hard to track.

	But again, all this is a long way around just looking at the
	elapsed times in the 'Frames' report, which are *realtime information*.
	The Elapsed time for each frame changes while the frame is rendering.

--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Fax: (Tel# suppressed)
Cel: (Tel# suppressed)

    [..] put the Frames button on 'repeat'
    (Hit "REP", then hit "Frames"), and then monitor the ELAPSED times
    for the busy frames to see how fast things are going.

My current issue with this is that the render farm picks up all of my frames at the same time (well, clumps of 5 frames), and they all take about the same length of time. So the progress information that I get stays at 0% for the length of the render, and then suddenly jumps to 100% at the end.

	Hmm, are you *sure* you're looking at the "ELAPSED" time column
	in the "Frames" report? eg:                                         |
                                                                           \|/
                                                                            v
STAT FRAME   TRY HOSTNAME        PID     JOBID            START          ELAPSED  NOTES
Done 0109    3   geneva          1816    ontario.1        08/11,00:53:07 00:05:03
Run  0110    3   tower           2723    ontario.1        08/11,01:50:00 00:03:03
Run  0111    3   geneva          1244    ontario.1        08/11,01:50:00 00:03:03
Run  0112    3   geneva          1816    ontario.1        08/11,01:50:00 00:03:03
Run  0113    3   meade           12244   ontario.1        08/11,01:50:00 00:03:03

	Those numbers change while the frame is rendering.

	So if you know frames are taking about 05:00, then you can watch
	the elapsed times change for the "Run" frames.. 03:00... 04:00.. 05:00

	I can tell in the above the "Run" frames are 3 minutes into a 5 minute
	render, so those frames are about 3/5 complete. Batching works the same.

	Leave the Frames button in REP mode to see the report update automatically
	in "hands off" mode.

--
Greg Ercolano, erco@(email surpressed)
Rush Render Queue, http://seriss.com/rush/
Tel: (Tel# suppressed)
Fax: (Tel# suppressed)
Cel: (Tel# suppressed)