New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Robot Process library incorrectly buffers file pipe output #2457

Closed
IbraheemYSaleh opened this Issue Oct 11, 2016 · 9 comments

Comments

Projects
None yet
2 participants
@IbraheemYSaleh

IbraheemYSaleh commented Oct 11, 2016

While running the "Process.Run Process(command,stdout=/some/file,stderr=/some/file)" keyword with external programs that generate a lot of stdout data, RobotFramework seems to buffer the output before piping it to the file causing the commands to execute significantly slower than it's OperatingSystem.Run or external shell counterpart.

For example, using a db-query script which generates 174 MB of stdout data piped directly to a file, Process.Run Process takes about 150 seconds to complete while the script normally completes in about 17 seconds in the shell or the OperatinSystem Run methods.

  • This issue is also seen with the Process.Start Process keyword
  • Using Python's Subprocess.Popen directly completes in the expected, fast time frame. It is only not working properly in RobotFramework's abstraction of the process control functionality!
@pekkaklarck

This comment has been minimized.

Show comment
Hide comment
@pekkaklarck

pekkaklarck Oct 11, 2016

Member

Interesting. Could you investigate how this could ne fixed? Process library uses subrocess.Popen internally, but apparently some of the configuration slows it down.

Member

pekkaklarck commented Oct 11, 2016

Interesting. Could you investigate how this could ne fixed? Process library uses subrocess.Popen internally, but apparently some of the configuration slows it down.

@IbraheemYSaleh

This comment has been minimized.

Show comment
Hide comment
@IbraheemYSaleh

IbraheemYSaleh Oct 12, 2016

Ughhh... I can only reproduce this using the java based Robot runners--pybot works fine (I'm trying to build this test framework into our maven build system so I'm not sure if switching to pybot is an option yet). On top of that, using a simple 'Run Process cat /path/to/large/textfile stdout=/path/to/out/file' test Robot program isn't enough to reproduce the issue. I have to use the java-based db-query application that I am running.

I ran an strace on both the pybot and the java robot runners. The only thing I noticed is that the java robot runner seems to use about 20 system write calls for every 1 system write call that the pybot runner uses. It seems to be chunking its data differently (10 bytes per write vs variable bytes per write)?

Eg a Single CSV record from the Pybot Runner:
1334 write(1, ""Xxx","70","xxx-xxx-7","x-xxxx""..., 191) = 191

Similar Single CSV record from the Java Robot Runner:
1381 write(47, "ED_INT"\n"X", 10) = 10
1381 write(47, "xx","70","", 10) = 10
1381 write(47, "xxx-xxxx-7", 10) = 10
1381 write(47, "","x-xxxx"", 10) = 10
1381 write(47, ","0","0","", 10) = 10
1381 write(47, "XXX_XX_XXX", 10) = 10
1381 write(47, "_XXXXX_A_F", 10) = 10
1381 write(47, "AILURE",""", 10) = 10
1381 write(47, ","2016-285", 10) = 10
1381 write(47, "T21:54:28.", 10) = 10
1381 write(47, "060","2013", 10) = 10
1381 write(47, "-178T01:30", 10) = 10
1381 write(47, ":49.198","", 10) = 10
1381 write(47, "0425568774", 10) = 10
1381 write(47, ".50000","1", 10) = 10
1381 write(47, "","","Read", 10) = 10
1381 write(47, "y","NONE",", 10) = 10
1381 write(47, ""NONE","tr", 10) = 10
1381 write(47, "ue","STATU", 10) = 10

I don't know what would cause this or how I might control it. I'm guessing it's probably time to start looking for a workaround to using the java robot runner or throw out using Process at this point rather than figure out what's actually going on here.

IbraheemYSaleh commented Oct 12, 2016

Ughhh... I can only reproduce this using the java based Robot runners--pybot works fine (I'm trying to build this test framework into our maven build system so I'm not sure if switching to pybot is an option yet). On top of that, using a simple 'Run Process cat /path/to/large/textfile stdout=/path/to/out/file' test Robot program isn't enough to reproduce the issue. I have to use the java-based db-query application that I am running.

I ran an strace on both the pybot and the java robot runners. The only thing I noticed is that the java robot runner seems to use about 20 system write calls for every 1 system write call that the pybot runner uses. It seems to be chunking its data differently (10 bytes per write vs variable bytes per write)?

Eg a Single CSV record from the Pybot Runner:
1334 write(1, ""Xxx","70","xxx-xxx-7","x-xxxx""..., 191) = 191

Similar Single CSV record from the Java Robot Runner:
1381 write(47, "ED_INT"\n"X", 10) = 10
1381 write(47, "xx","70","", 10) = 10
1381 write(47, "xxx-xxxx-7", 10) = 10
1381 write(47, "","x-xxxx"", 10) = 10
1381 write(47, ","0","0","", 10) = 10
1381 write(47, "XXX_XX_XXX", 10) = 10
1381 write(47, "_XXXXX_A_F", 10) = 10
1381 write(47, "AILURE",""", 10) = 10
1381 write(47, ","2016-285", 10) = 10
1381 write(47, "T21:54:28.", 10) = 10
1381 write(47, "060","2013", 10) = 10
1381 write(47, "-178T01:30", 10) = 10
1381 write(47, ":49.198","", 10) = 10
1381 write(47, "0425568774", 10) = 10
1381 write(47, ".50000","1", 10) = 10
1381 write(47, "","","Read", 10) = 10
1381 write(47, "y","NONE",", 10) = 10
1381 write(47, ""NONE","tr", 10) = 10
1381 write(47, "ue","STATU", 10) = 10

I don't know what would cause this or how I might control it. I'm guessing it's probably time to start looking for a workaround to using the java robot runner or throw out using Process at this point rather than figure out what's actually going on here.

@IbraheemYSaleh

This comment has been minimized.

Show comment
Hide comment
@IbraheemYSaleh

IbraheemYSaleh Oct 12, 2016

I was able to reproduce this using just java-Robot (jython) with Run Process directly calling my large mysql query (skipping my intermediate java application parsing) ... Since that is the case, I believe it's likely that other people will run into this bug at some point...

However, this doesn't seem to be a Robot bug but rather a bug with Jython (unless the jar version of Robot uses something else). I will create the bug report there instead.

IbraheemYSaleh commented Oct 12, 2016

I was able to reproduce this using just java-Robot (jython) with Run Process directly calling my large mysql query (skipping my intermediate java application parsing) ... Since that is the case, I believe it's likely that other people will run into this bug at some point...

However, this doesn't seem to be a Robot bug but rather a bug with Jython (unless the jar version of Robot uses something else). I will create the bug report there instead.

@pekkaklarck

This comment has been minimized.

Show comment
Hide comment
@pekkaklarck

pekkaklarck Oct 12, 2016

Member

Yeah, definitely sounds like a bug in Jython. It would be interesting to know what's the actual root cause, though. If we were lucky, we could perhaps workaround it on the Process library somehow.

Member

pekkaklarck commented Oct 12, 2016

Yeah, definitely sounds like a bug in Jython. It would be interesting to know what's the actual root cause, though. If we were lucky, we could perhaps workaround it on the Process library somehow.

@pekkaklarck pekkaklarck reopened this Oct 12, 2016

@pekkaklarck

This comment has been minimized.

Show comment
Hide comment
@pekkaklarck

pekkaklarck Oct 12, 2016

Member

Ooops, didn't mean to close this at this point. Damn GitHub for having Close and comment button next to Comment button...

Member

pekkaklarck commented Oct 12, 2016

Ooops, didn't mean to close this at this point. Damn GitHub for having Close and comment button next to Comment button...

@IbraheemYSaleh

This comment has been minimized.

Show comment
Hide comment
@IbraheemYSaleh

IbraheemYSaleh Oct 12, 2016

I don't really know anything about how Jython converts python's Subprocess to Java but that seems to be what they're doing wrong.

Looking at the strace, File Descriptor 47 is a custom descriptor created by Jython while File Descriptor 1 is actually stdout. So... Jython needs to correctly direct stdout output to stdout instead of whatever they're actually doing with their Subprocess interpretation/implementation? Just a thought from somebody that knows nothing :)

IbraheemYSaleh commented Oct 12, 2016

I don't really know anything about how Jython converts python's Subprocess to Java but that seems to be what they're doing wrong.

Looking at the strace, File Descriptor 47 is a custom descriptor created by Jython while File Descriptor 1 is actually stdout. So... Jython needs to correctly direct stdout output to stdout instead of whatever they're actually doing with their Subprocess interpretation/implementation? Just a thought from somebody that knows nothing :)

@pekkaklarck

This comment has been minimized.

Show comment
Hide comment
@pekkaklarck

pekkaklarck Jan 30, 2017

Member

Any new info about this issue? Have you tested do you get same slowdown if you use subprocess directly using Jython? Do you have an example that demonstrates this problem that I could try running locally?

Member

pekkaklarck commented Jan 30, 2017

Any new info about this issue? Have you tested do you get same slowdown if you use subprocess directly using Jython? Do you have an example that demonstrates this problem that I could try running locally?

@pekkaklarck

This comment has been minimized.

Show comment
Hide comment
@pekkaklarck

pekkaklarck Jan 30, 2017

Member

And again I clicked the wrong button when just trying to add a comment!!

Member

pekkaklarck commented Jan 30, 2017

And again I clicked the wrong button when just trying to add a comment!!

@pekkaklarck pekkaklarck reopened this Jan 30, 2017

@pekkaklarck

This comment has been minimized.

Show comment
Hide comment
@pekkaklarck

pekkaklarck Apr 23, 2018

Member

Closing due to lack of new info and an example I could try myself.

Member

pekkaklarck commented Apr 23, 2018

Closing due to lack of new info and an example I could try myself.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment