AWS Thinkbox Discussion Forums

long stdout line -> hanging slave for 90 mins

Deprecated Deadline 6 Bug Reports
#1

Ok, we have a very strange issue here…

We are still investigating whats going on, but our theory right now is that its somehow related to the stdout handling between maya and the deadline slave.

So… We have our own internal logging system that logs all activity from our pipeline to an html file, with time stamps. We have a somewhat long processing job that locally runs in about ~20 mins, but on deadline it takes ~110 mins. After looking at the logs, we found something really odd… The deadline timestamps go up to 110 mins, but our own internal timestamps are in fact taking only 20 mins! WTH you could say!

The first lines of the log (green is deadline timestamps, blue is our timestamps from our log - printed to the stdout):

2014-06-26 13:58:21: 0: STDOUT: scLog Maya initializing in farm mode (printing to stdout)
2014-06-26 13:58:21: 0: STDOUT: Thu Jun 26 13:58:21 2014 (+0ms) : (Maya): debug : New log file created using scLog v0.10
2014-06-26 13:58:21: 0: STDOUT: Thu Jun 26 13:58:21 2014 (+0ms) : (Maya): debug : clearInactiveLogs

By the end of the log, things get grossly out of sync (by about 72 mins):

2014-06-26 16:26:20: 0: STDOUT: Thu Jun 26 15:14:19 2014 (+0ms) : (scl_pipeline_sceneBuilder): sTitle:[Maya]:lapro3015:AnimTechCheck:SQU_039_0740@sea
2014-06-26 16:26:20: 0: STDOUT: Thu Jun 26 15:14:19 2014 (+0ms) : (scl_pipeline_sceneBuilder): sMsg:Machine : lapro3015

Looking through the log, things get mixed up at a line of output from maya, thats extremely long (211006 characters long…). A maya script line is outputting a warning that basically lists a bunch of objectnames in a single line.
It appears that the way deadline reads this line takes about 86 minutes or so… very odd.

We get this:

2014-06-26 15:01:44: 0: STDOUT: Thu Jun 26 15:01:27 2014 (+0ms) : (Maya): PUBLISH : activating ShaderOverrideNode@ScanlineData_ShaderOverrideNode1
2014-06-26 15:01:44: 0: STDOUT: Thu Jun 26 15:01:27 2014 (+0ms) : PUBLISH : activating ShaderOverrideNode@ScanlineData_ShaderOverrideNode1
2014-06-26 16:26:01: 0: WARNING: Strict error checking on, ignoring the following unrecognized error or warning. If it is fatal, please email support@thinkboxsoftware.com with the error message.
2014-06-26 16:26:01: 0: STDOUT: Warning: Cannot add the following items to the set since the set has restrictions on membership: chrSailorC_303_1:xtrs_l_high_upLegRoll chrSailorC_303_1:xtrs_l_high_leg … *** TRUNCATED THE 211006 CHARACTERS ***
2014-06-26 16:26:01: 0: STDOUT: Thu Jun 26 15:01:41 2014 (+14024ms) : (Maya): PUBLISH STEP 5/7 : Step time: 14.02 secs. Avg step time: 8.90 secs. Total time spent: 00h:00m:17s Estimated time left: 00h:00m:17s (step 2/4)

#2

Hey Laszlo,

Do you have the “Limit the number of characters per line” option enabled in your repository options?
thinkboxsoftware.com/deadlin … Settings_2

Very long lines of stdout can basically choke the stdout parsing system in the Deadline plugin. We put this option in place for this very reason.

If it is enabled, then line of stdout should never have been processed, but since the line was processed, it makes me think that either this option is disabled, or it’s enabled and the limit is very high, or there is a bug.

Thanks!
Ryan

#3

The option is set to 5000 characters. Copy pasting from the log reveals it has 200k+ characters though.

Although, why does it choke on reading it? Reading 200kB shouldnt take 70 mins,…

#4

Interesting. We’ve logged this as an issue, and will have to investigate further.

Our stdout parsers use regular expressions, and running a regular expression against 200K+ characters will be slow. In addition, it’s made worse in the Maya plugin because we check the line of stdout for specific error messages to determine if it’s fatal or not.

For the script that prints out that really long line, is that something you guys control? If so, could you change it to print out one object per line for now?

Cheers,
Ryan

#5

So this is a bug. It turns out the limit only gets applied to the DeadlinePlugin object returned by the plugin, but it doesn’t get applied to any ManagedProcesses that the object launches. So the issue you’re seeing is an issue for the MayaBatch plugin, but not for the MayaCmd plugin.

This issue will be fixed in Deadline 7, but as a workaround for now, you can add this to the init function for the MayaBatchProcess class in MayaBatch.py:

self.MaxHandledLineSize = 5000

Cheers,
Ryan

#6

Cool, thanks ill try that!

I tried running some regular expressions against that 200kB line, and they return instantly. I think there is something wrong with maybe the buffered read? I used the re python library, so another option is that .net regex matching is not as good?

#7 
self.MaxHandledLineSize = 5000

Seems to have done the trick, it went from ~70 mins to ~10 seconds to process that line.
Im still confused as to why it takes that long though… i couldn’t repro such long processing times with regexes

Privacy | Site terms | Cookie preferences