bugGNU Octave - Bugs: bug #55940, pause() takes too long if you call...

 
 

bug #55940: pause() takes too long if you call it a bunch

Submitted by:  Andrew Janke <apjanke>
Submitted on:  Sun 17 Mar 2019 02:40:10 PM UTC  
 
Category:  Octave Function Severity:  3 - Normal
Priority:  5 - Normal Item Group:  Incorrect Result
Status:  Confirmed Assigned to:  None
Originator Name:  Open/Closed:  Open
Release:  5.1.0 Operating System:  Mac OS

Add a New Comment(Rich Markup)
   

You are not logged in

Please log in, so followups can be emailed to you.

 

( Jump to the original submission)

Wed 20 Mar 2019 05:39:48 PM UTC, comment #35:

I don't see much in the dtruss log that helps me pinpoint anything.

If it is a process scheduling issue, what happens if you give it an increased priority using the nice shell command?

Steps to try

1) start Octave
2) Find PID of Octave in another terminal
3) renice -n -20 -p PID
4) now run delay.oct file in Octave

Also, another guess at something to try, maybe there is an interaction with the Readline event hook.

Try starting octave like so

and then running the delay.oct file.

Rik <rik5>
Project Administrator
Wed 20 Mar 2019 01:20:18 AM UTC, comment #34:

May be this is useful:

Dmitri.
--

Dmitri A. Sergatskov <dasergatskov>
Wed 20 Mar 2019 12:49:37 AM UTC, comment #33:

No, you're probably right to use the first form. I forgot that the "octave" binary does a fork and exec so the original program does exit immediately.

Rik <rik5>
Project Administrator
Wed 20 Mar 2019 12:18:18 AM UTC, comment #32:

> strace octave -f -q tst_delay.m > strace.log


That didn't work. I tried:

sudo dtruss /Applications/Octave-5.1.0.app/Contents/Resources/usr/opt/octave-octave-app@5.1.0/bin/octave -f -q tst_delay.m &> dtruss-tst_delay.log

But it just exited right away.

I'm probably just not using dtruss right; I know its interface is not identical to strace.

Andrew Janke <apjanke>
Wed 20 Mar 2019 12:08:13 AM UTC, comment #31:

Oho, here we go:

  • Start octave in one terminal. Use getpid to get its pid
  • In another terminal, `sudo dtruss -p <octave_pid> &> dtruss.log`

Here's what I ran in octave:

And here's the resulting dtruss.log: file #46590

Andrew Janke <apjanke>
Wed 20 Mar 2019 12:07:07 AM UTC, comment #30:

Oho, here we go:

  • Start octave in one terminal. Use getpid to get its pid
  • In another terminal, `sudo dtruss -p <octave_pid> &> dtruss.log`

Here's what I ran in octave:

And h

(file #46590)

Andrew Janke <apjanke>
Tue 19 Mar 2019 11:58:08 PM UTC, comment #29:

Another choice is to put the original Octave code in to an m-file (I'm attaching tst_delay.m to this bug report) and then run

(file #46589)

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 11:54:17 PM UTC, comment #28:

if it is anything like "strace" you should be able to run interactive re-directing stderr:

Dmitri.

Dmitri A. Sergatskov <dasergatskov>
Tue 19 Mar 2019 11:49:16 PM UTC, comment #27:

> This is really bizarre. Is the OS scheduler doing something odd? Maybe it notices that the process is sleeping a lot and it schedules it for infrequent re-activation?


Your guess is as good as mine. That's what it kinda sounds like. I'm no expert in this area, and I don't know how to examine the behavior of the scheduler. My naive Googling for it isn't helping yet.

I'm reading through this book off and on: https://www.amazon.com/Mac-OS-iOS-Internals-Apples/dp/1118057651. Maybe it will help.

Andrew Janke <apjanke>
Tue 19 Mar 2019 11:46:36 PM UTC, comment #26:

> Can you run it through MacOS "strace" equivalent ("dtruss"?) and see if that gives some clues?


I can't get this working. When run under "dtruss", octave just seems to quit right away instead of running code.

Command I tried:

sudo dtruss /Applications/Octave-5.1.0.app/Contents/Resources/usr/opt/octave-octave-app@5.1.0/bin/octave --eval 'delay' &> dtruss-octave-delay.log

Here's my log file: file #46588

Andrew Janke <apjanke>
Tue 19 Mar 2019 11:23:15 PM UTC, comment #25:

This is really bizarre. Is the OS scheduler doing something odd? Maybe it notices that the process is sleeping a lot and it schedules it for infrequent re-activation?

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 10:52:22 PM UTC, comment #24:

Can you run it through MacOS "strace" equivalent ("dtruss"?) and see if that gives some clues?

Dmitri.
--

Dmitri A. Sergatskov <dasergatskov>
Tue 19 Mar 2019 10:15:20 PM UTC, comment #23:

Thanks!

Minor bug in delay.cpp:

That should be "option == 2", otherwise the else case (for direct call of nanosleep) will never get hit.

I've added it to my test repo and modified the output so it only reports too-long pauses, to make it easier to copy-and-paste output here. A simple "." indicates a sleep that took less than 2x as long as requested. https://github.com/apjanke/test-nanosleep-for-octave/blob/1fa1269bcdad7f4d88cdee1b0037b34f6be526ca/src-octfiles/delay.cpp

I've compiled it and run it under Octave 5.1.0. (Octave default is not building for me right now.)

Results:

Or:

For a bit, I thought that the `octave::sleep (x, false)` case didn't cause problems, but then I ran this:

The direct nanosleep call causes problems, too!

WTF?

So, to me, that doesn't sound like it's a problem in the pause() logic, but something else.

Andrew Janke <apjanke>
Tue 19 Mar 2019 09:06:14 PM UTC, comment #22:

@Andrew: Can you try the attached delay.cpp? Compile it as a .octfile with

Then try running it with options 0, 1, and 2. The documentation is

This might help distinguish which code path is failing.

(file #46584)

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 05:51:37 PM UTC, comment #21:

> Is it possible that the delay is accurate when run in Octave, but the reporting is incorrect? In other words, is there something wrong with tic/toc?


I don't think so. I sat there watching it, and it definitely took 20-30 seconds sometimes.

The only reason I noticed this in the first place is that pause started taking so long that I thought my code was hung.

Andrew Janke <apjanke>
Tue 19 Mar 2019 05:47:14 PM UTC, comment #20:

Is it possible that the delay is accurate when run in Octave, but the reporting is incorrect? In other words, is there something wrong with tic/toc?

I put the following code in a file tst_delay.m

Then I ran

The third column is wall time which is about 20 seconds and is what I would expect for 100, 0.2 second delays.

Rik <rik5>
Project Administrator
Tue 19 Mar 2019 04:53:27 PM UTC, comment #19:

I got the test project building on my system too, with Mike's help.

When I run the test on the same machine that shows the weird long pause behavior in Octave, its pauses go for 200 ms each time, with only 1 or two ms variation. It doesn't reproduce the weird pause behavior.

Andrew Janke <apjanke>
Mon 18 Mar 2019 08:57:23 PM UTC, comment #18:

Your test project works for me, and in fact on my system the gnulib replacement is also used, I get "mishandles large arguments", so the shim function "rpl_nanosleep" is used.

The test program runs to 99 on my system with 0.2 seconds each time, and I also can't reproduce this in Octave.

Mike Miller <mtmiller>
Project Administrator
Mon 18 Mar 2019 07:51:24 PM UTC, comment #17:

Anybody know enough about gnulib and autotools to help me get a minimal test program working?

https://github.com/apjanke/test-nanosleep-for-octave

Andrew Janke <apjanke>
Mon 18 Mar 2019 05:21:25 PM UTC, comment #16:

> … that uses the right gnulib nanosleep wrapper and see how it behaves.


Darn it. I'll need to get set up for gnulib use. Stand by...

Andrew Janke <apjanke>
Mon 18 Mar 2019 05:20:52 PM UTC, comment #15:

Test program:

Results:

It's within a few milliseconds of 200 ms each time I run it.

Andrew Janke <apjanke>
Mon 18 Mar 2019 05:17:09 PM UTC, comment #14:

> write a stand-alone C++ program that calls nanosleep and see if it also behaves incorrectly.


… that uses the right gnulib nanosleep wrapper and see how it behaves.

On macOS, Andrew should be using the nanosleep wrapper in libgnu/nanosleep.c inside the '#if HAVE_BUG_BIG_NANOSLEEP' conditional.

Mike Miller <mtmiller>
Project Administrator
Mon 18 Mar 2019 05:12:42 PM UTC, comment #13:

@Andrew: Oops, my comment #12 got interspersed with jwe's comments. We are both looking for the same thing. Is this a problem with Octave or a problem with the system library?

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 05:08:51 PM UTC, comment #12:

To test, you could write a stand-alone C++ program that calls nanosleep and see if it also behaves incorrectly.

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 05:04:56 PM UTC, comment #11:

When I first made pause interruptible (http://hg.savannah.gnu.org/hgweb/octave/rev/6b3c78f84d3b in response to bug #52876) it was not handling graphics events during the pause. Now that it does process graphics events while paused, I agree with Rik that we need to fix it to account for any time spent processing those events. Also, what should happen if one of those graphics events calls pause?

Regardless, it is surprising to me that any graphics events would cause this much of a delay. I see up to 500ms extra delay, but usually around 10ms.

To verify that it is graphics event processing that is causing the trouble, what happens if you remove the calls to gh_manager::process_events in the void sleep (double seconds, bool do_graphics_events) function in libinterp/corefcn/utils.cc?

Hmm, what Andrew wrote in comment #4 indicates that maybe it isn't the graphics events causing the trouble?

Could you also insert some statements to trace the calls to the nanosleep wrapper to see whether it is a general delay (all calls take about the same amount of time, just longer than expected) or if most calls take approximately the requested delay and some MUCH longer?

John W. Eaton <jwe>
Project Administrator
Mon 18 Mar 2019 04:47:51 PM UTC, comment #10:

> Thanks. I think re-coding is required then.


The one thing that makes me question this is that the delay also happens when calling java.lang.Thread.sleep(), which is unrelated to Octave's pause() code.

Andrew Janke <apjanke>
Mon 18 Mar 2019 04:35:00 PM UTC, comment #9:

Thanks. I think re-coding is required then.

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 04:17:28 PM UTC, comment #8:

> Also, when testing, are you starting octave with -f so there are no user configuration settings that might be affecting this?


No. But I tried it just now, and it's showing the same behavior.

Andrew Janke <apjanke>
Mon 18 Mar 2019 04:10:34 PM UTC, comment #7:

Also, when testing, are you starting octave with -f so there are no user configuration settings that might be affecting this?

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 04:09:33 PM UTC, comment #6:

> As a further test, could you try changing the pause amount to an integral number of seconds (i.e., try 1) and see what happens?


Ouch.

Andrew Janke <apjanke>
Mon 18 Mar 2019 03:50:57 PM UTC, comment #5:

So, I guess we can confirm this as being real, but only for Mac platforms.

The Octave code for the sleep() call is in libinterp/corefcn/utils.cc (sleep).

As a further test, could you try changing the pause amount to an integral number of seconds (i.e., try 1) and see what happens?

Looking at the code, it is much more complicated than one would have first thought. I imagined that Octave was just calling the library function sleep or nanosleep with the appropriate delay.

Instead, in order to have the interpreter respond interactively to signals (such as Ctrl+C), the total delay is split in to 100 millisecond segments and after every segment Octave checks whether there has been a signal event. It also runs any GUI or plot events if the do_graphics_events input to the function is true. That could be where the variable delay is getting inserted.

I think, irregardless of the fact that this seems to work on Linux, that this is not the right strategy. I think we should use something similar to what Pantxo coded for movie.m which I will quote below.

The point is that any work done in the loop is accounted for and reduces the length of the pause. If the time to pause is negative--because so much work was done in the loop--then pause is skipped which gets the delay engine back on track.

This would need to be re-coded in C++, but it isn't that hard.

Rik <rik5>
Project Administrator
Mon 18 Mar 2019 02:20:17 PM UTC, comment #4:

I can't reproduce this on Linux or Windows, even in VMs on the original machine where this first appeared.

I can reproduce it on other Mac machines. The first one where I saw it was angharad, a 5K iMac running Mojave. Here's behavior on toast, my 13" MacBook Pro, under 5.1.0, while the machine is lightly loaded.

Happens for me in 4.4.1, 5.1.0, and default. Again, on this machine, it only happens in the CLI, not the GUI of the same Octave, even if run at the same time as a CLI octave process is exhibiting this behavior.

One thing I noticed is that it takes a while for Octave to respond to Ctrl-C inputs when this is happening. So it seems like one of the individual sleep intervals or graphics-handling steps in octave::sleep() is taking a while. And the fact that java.lang.Thread.sleep is also taking a long time suggests that it's not octave::sleep's code that's doing anything weird; it's something about the overall process or machine state that's causing regular sleeps to take a long time.

Andrew Janke <apjanke>
Mon 18 Mar 2019 12:57:43 PM UTC, comment #3:

This also works for me on linux and Windows (Octave 4.4.0).

Pantxo Diribarne <pantxo>
Project Member
Mon 18 Mar 2019 04:37:42 AM UTC, comment #2:

This works for me, but I'm running on Linux.

It would be good to see if anyone else can replicate this.

Rik <rik5>
Project Administrator
Sun 17 Mar 2019 02:50:26 PM UTC, comment #1:

Seems to affect java.lang.Thread.sleep, too.

My system isn't heavily loaded, so this is kind of surprising.

Andrew Janke <apjanke>
Sun 17 Mar 2019 02:40:10 PM UTC, original submission:

If I call pause() several times in a row, with only a little work done in between calls, eventually pause() starts taking much longer than the specified time, causing hangs.

```
octave:1> for i = 1:100; t0 = tic; pause(0.2); te = toc(t0); fprintf("%.3f\n", te); endfor
0.201
0.205
0.201
0.201
0.202
0.201
0.205
0.205
0.204
0.205
0.201
0.200
0.201
0.201
0.201
0.204
0.204
0.204
0.203
0.201
0.201
0.204
0.200
0.209
0.204
0.204
0.204
0.202
0.201
0.202
0.202
0.200
0.201
0.202
0.201
0.201
3.062
5.919
1.926
1.296
5.152
1.621
20.200
8.701
2.147
5.800
2.533
2.446
0.587
3.142
4.628
0.213
8.256
0.253
1.068
10.200
14.527
20.200
```

Only seems to affect CLI Octave; doesn't happen in the GUI Octave.

Affects 4.4.1, 5.1.0, and default.

Andrew Janke <apjanke>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #46590:  dtruss.log.gz added by apjanke (3KiB - application/x-gzip)
file #46589:  tst_delay.m added by rik5 (88B - text/x-matlab)
file #46588:  dtruss-octave-delay_not-working-01.log added by apjanke (3KiB - application/octet-stream)
file #46584:  delay.cpp added by rik5 (1KiB - text/x-c++src)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by dasergatskov (Posted a comment)
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by pantxo (Posted a comment)
  • -email is unavailable- added by rik5 (Posted a comment)
  • -email is unavailable- added by apjanke (Submitted the item)
  •  

    Do you think this task is very important?
    If so, you can add your encouragement to it.
    This task has 0 encouragements so far.

    Only project members can vote.

     

     

     

    Follow 6 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-03-20 apjanke Attached File- => Added dtruss.log.gz, #46590
    2019-03-19 rik5 Attached File- => Added tst_delay.m, #46589
    2019-03-19 apjanke Attached File- => Added dtruss-octave-delay_not-working-01.log, #46588
    2019-03-19 rik5 Attached File- => Added delay.cpp, #46584
    2019-03-18 rik5 StatusWorks For Me => Confirmed
    2019-03-18 rik5 StatusNone => Works For Me

    Back to the top


    Powered by Savane 3.4