bugGNU Octave - Bugs: bug #45475, output calling "more"...

 
 

bug #45475: output calling "more" has 10 second delay?

Submitted by:  Nicholas Jankowski <nrjank>
Submitted on:  Sat 04 Jul 2015 05:39:51 PM UTC  
 
Category: Octave FunctionSeverity: 3 - Normal
Priority: 5 - NormalItem Group: Performance
Status: NoneAssigned to: None
Originator Name: Nick JankowskiOpen/Closed: Open
Release: 4.2.0Operating System: Microsoft Windows

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 Jump to the original submission)

Tue 08 Aug 2017 01:32:07 AM UTC, comment #30:

Regarding cygwin, if you look at a couple of the comment 16-19 links, they referred to the msys tools which are apparently pulling code from the cygwin project. there were a few tools showing delays due to seemingly unrelated network configuration info

Nicholas Jankowski <nrjank>
Mon 07 Aug 2017 11:18:16 PM UTC, comment #29:

Oh, I think I misunderstood comment #27. You are running less.exe in a shell command window? Does the same thing happen if you are in Octave's bin directory and use cat.exe to display the file?

John W. Eaton <jwe>
Project Administrator
Mon 07 Aug 2017 11:13:02 PM UTC, comment #28:

Johannes, could you try again with the Octave PAGER variable set to "cat.exe" and PAGER_FLAGS set to ""? If output appears immediately with cat, then I'd say the problem is with less. But if it is still slow, then I'd guess that the problem is due to executing the separate process for the pager. That could certainly be related to networking, but I don't have any idea exactly how.

The version of less should be coming from the Octave bin directory. It is built along with Octave and, like the rest of the tools distributed with the Octave binary installer, doesn't depend on Cygwin.

John W. Eaton <jwe>
Project Administrator
Mon 07 Aug 2017 09:50:26 PM UTC, comment #27:

The results of my previous test made me think about the Cygwin utilities implementing the pager. I assume that the tool “less.exe” is acting as pager in Octave – at least in the default context I ran my tests.

This is the list of my network adapters (the “x” marks an active adapter) - in regular operations mode they all are active:
(x ) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(X) VMWare Virtual Ethernet Adapter for VMNet1
(X) VMWare Virtual Ethernet Adapter for VMNet8

The idea is to simply print a text file and measure the time it takes to display the first screen output. This is the corresponding test command sequence:

cd \Octave\Octave-4.2.1\bin
less texindex.bat
q
<wait 30 seconds>
less texindex.bat
q
<wait 30 seconds>
… <8 more iterations>

I measured the time between pressing [Enter] after having typed in “less texindex.bat” and the display of the first result page.

Test run 1L (10 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(x) VMWare Virtual Ethernet Adapter for VMNet1
(x) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]: 0 4 0 7 0 7 0 7 0 7

Test run 2L (30 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(x) VMWare Virtual Ethernet Adapter for VMNet1
(x) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]: 8 8 8 8 8 8 8 8 8 8

Test run 3L (30 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]: 4 3 3 3 3 3 3 3 3 3

Test run 4L (30 second delay)
============================
( ) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
( ) Intel Dual Band Wireless-N 7265
( ) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]: 0 0 0 0 0 0 0 0 0 0

Again, I took the times with a manual stopwatch so the values are just good approximations. However, you can see the dependency between the screen output time and the number of active network adapters. Especially the VMWare adapters cause a significant delay.
Just one remark: When I turn off paging (enter “more” at the Octave prompt), the speed of screen output gets blazingly fast no matter how many network adapters are active!

Thus, the tool “less.exe” seems to be the culprit: It is messing around with the network adapters.

Johannes Bruns <jbruns>
Sun 06 Aug 2017 04:47:02 PM UTC, comment #26:

To shed some light on this issue, I performed a test with clearly defined conditions. Let me tell you first that I ran the test on my computer which is connected to the Internet via a 16 MBPS ADSL connection.

This is the list of my network adapters (the “x” marks an active adapter) - in regular operations mode they all are active:

(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(X) VMWare Virtual Ethernet Adapter for VMNet1
(X) VMWare Virtual Ethernet Adapter for VMNet8

This is the content of the script Test_Output.m to generate test data to show:

% Test the delay of output on screen
Theta1 = ones(10,11);
Theta2 = 2 * ones(10,11);
Theta3 = 3 * ones(1,11);
thetaVec = [ Theta1(:) ; Theta2(:) ; Theta3(:) ];

The idea is to simply list the vector thetaVec ten times with some delay between the iteration. This is the corresponding test command sequence:

&lt;Launch Octave GUI&gt;
Test_Output [Enter]
thetaVec [Enter]
q
&lt;wait 15 seconds&gt;
thetaVec [Enter]
q
&lt;wait 15 seconds&gt;
… &lt;8 more iterations&gt;
quit

I measured the time between pressing [Enter] after having typed in “thetaVec” and the display of the first result page.

Test run 1 (15 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(X) VMWare Virtual Ethernet Adapter for VMNet1
(X) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
7 4 0 7 0 7 0 7 0 4

Test run 2 (20 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(X) VMWare Virtual Ethernet Adapter for VMNet1
(X) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
7 7 7 4 7 4 0 7 4 7

Test run 3 (30 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(X) VMWare Virtual Ethernet Adapter for VMNet1
(X) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
7 7 4 7 7 7 7 7 7 7

Test run 4 (30 second delay)
============================
( ) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
( ) Intel Dual Band Wireless-N 7265
( ) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:

  1. 0 0 0 0 0 0 0 0 0

Test run 5 (30 second delay)
============================
( ) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
( ) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
3 3 3 3 3 3 3 3 3 3

Test run 6 (30 second delay)
============================
( ) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
( ) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
4 3 3 3 3 3 3 3 3 3

Test run 7 (30 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
3 3 3 3 3 3 3 3 3 3

In the following test runs I called “help plot” instead of “thetaVec”: I measured the time between pressing [Enter] after having typed in “help plot” and the display of the first result page.

Test run 8 (30 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
(x) VMWare Virtual Ethernet Adapter for VMNet1
(x) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
5 10 10 10 10 10 10 10 10 10

Test run 9 (30 second delay)
============================
(x) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
(x) Intel Dual Band Wireless-N 7265
(x) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
5 5 5 5 5 5 5 5 5 5

Test run 10 (30 second delay)
============================
( ) Cisco AnyConnect Secure Mobile Client Virtual Miniport Adapter for Windows x64
( ) Intel Dual Band Wireless-N 7265
( ) Intel Ethernet Connection (3) I218-LM
( ) VMWare Virtual Ethernet Adapter for VMNet1
( ) VMWare Virtual Ethernet Adapter for VMNet8
Measured delays of screen output [sec]:
3 3 3 3 3 3 3 3 3 3

I took the times with a manual stopwatch so the values are just good approximations. However, you can see the dependency between the screen output time and the number of active network adapters. Especially the VMWare adapters cause a significant delay.

Johannes Bruns <jbruns>
Mon 31 Jul 2017 03:21:28 PM UTC, comment #25:

trying it out a bit now, it's just as random and non-repeatable for me as it was 2 years ago.

Opening octave for the first time today, first command 'help plot', there was a 6-7 second delay before the text appears. Repeat help commands, or other help commands, or other text, almost no delay after that, and no delay on 'rand(100,1)'. Closing/restarting octave, still no measurable delay. haven't tried a reboot.

Nicholas Jankowski <nrjank>
Mon 31 Jul 2017 04:24:29 AM UTC, comment #24:

Does all output that goes through the pager take a long time to appear, or just some?

You say "help plot" takes a long time to appear, but what about something like "rand (100, 1)"?

John W. Eaton <jwe>
Project Administrator
Sun 30 Jul 2017 06:23:18 PM UTC, comment #23:

I also noticed the delay mentioned in this thread. I am running Octave 4.2.1 on a Windows 7 computer (x86_64-w64-mingw32).

You can easily watch the effect of the delayed out when you enter for instance "help plot" in the Command Window. I measured a delay of ten seconds today.

Johannes Bruns <jbruns>
Thu 29 Jun 2017 01:33:43 PM UTC, comment #22:

that option was already deselected in my installation.

Nicholas Jankowski <nrjank>
Thu 29 Jun 2017 12:25:12 PM UTC, comment #21:

Perhaps related, on startup:

On my 4.2.1, normal GUI startup seems to be about 4-5 secs before the command prompt is ready to allow typing. (I am connected on the network)

If I pull the network cable, if I pull the network cable it then takes at around 20 secs before I can type anything.

If I change the settings in Octave to deselect Network->Allow octave to connect to the octave website, it takes 7-8 seconds (with network disabled)

What happens if you change the settings in Octave to deselect Network->Allow octave to connect to the octave website ?

John Donoghue <lostbard>
Project Member
Thu 29 Jun 2017 04:33:53 AM UTC, comment #20:

I add John Donoghue to CC list because he is working extensively windows build through mxe-octave.

Tatsuro MATSUOKA <tmacchant>
Thu 29 Jun 2017 01:00:53 AM UTC, comment #19:

First of all I have not seen such delay so that I cannot give valuable comment on this issue.

https://github.com/Alexpux/MSYS2-packages/issues/117

Perhaps this is not related. Msys embedded with octave is original MSYS but not MSYS2.

Slow start on octave for windows perhaps comes from reconstruction of fontconfig cash .

Tatsuro MATSUOKA <tmacchant>
Wed 28 Jun 2017 04:48:13 PM UTC, comment #18:

so:
tic; rand(300)
(press q "right away")
toc

1 - 1.421s

2 - 1.43 s (but Octave startup was 5-10sec slower with an active unconnected network adapter. gui loaded but command window blank white watiing 'welcome text')

3 - 1.73 s

4 - 1.47s (again slower startup)

5 - 1.40s (much faster startup than #2 with hardware switch off)

6 - 1.6s

I think all of those are within user error. and obviously I'm currently unable to recreate the delay. I didn't reboot the machine between tests, so I don't know if that's relevant. The slow start is interesting, however. wonder if that's related to the same issue.

Nicholas Jankowski <nrjank>
Wed 28 Jun 2017 03:37:34 PM UTC, comment #17:

This seems plausible and could be why the issue was so erratic.

According to that page and another linked page [1]:

According to many comments a workaround is:

But I have no idea what else this may affect in Octave's MSYS implementation.

If this is the case some version of the following should isolate noticeable differences, correct? I'll try them out:

#1 - domain controlled PC on the network. Start Octave. rand(300). count the seconds (or tic/toc i guess). close Octave.
#2 - disconnect domain controlled PC from network. start Octave. rand(300). count the seconds. close Octave.
#3 - have PC connected to network. start octave. disconnect PC from network. rand(300). count the seconds. close Octave.
#4 - disconnected PC. start Octave. connect PC to network. rand(300). count the seconds. close octave.
#5 - #2 but after disconnecting disable the previously active network adapter.
#6 - #3 but after disconnecting disable the previously active network adapter.

I've cc'd tmacchant on this since I believe he has a bit more insight into the windows build process and components. Hoping for an easy fix. It's been one of those nagging issues for some time. May let me take the 'more off' out of my octaverc.

[1] https://github.com/Alexpux/MSYS2-packages/issues/117

Nicholas Jankowski <nrjank>
Wed 28 Jun 2017 03:04:41 PM UTC, comment #16:

For me it seems to be related to the known issues of the MinGW environment - tools startup is delayed when runnnig on the domain-controlled machine being currently disconnected from the domain. See for example https://github.com/Alexpux/MSYS2-packages/issues/138

For me the workaround is to disable the network adapter.

Anonymous
Wed 28 Jun 2017 02:59:12 PM UTC, comment #15:

confirming that the delay is still present in 4.2.1 on Windows

Nicholas Jankowski <nrjank>
Thu 17 Nov 2016 02:00:54 PM UTC, comment #14:

still noticing similar delays in 4.2.0

Nicholas Jankowski <nrjank>
Mon 06 Jun 2016 12:25:01 AM UTC, comment #13:

It's definitely improved since I can no longer get it to happen randomly, just on the first call. I believe there are other open bugs related to figures taking a long time to appear the first time, and there's a hypothesis that it had something to do with the Windows font cache. Maybe something similar?

Nicholas Jankowski <nrjank>
Sun 05 Jun 2016 10:34:37 PM UTC, comment #12:

Thanks, Nicholas. It is good that some changes have accidentally helped this, but 9 seconds is still too long, so let's leave this open. I'll change the summary line: "20+" -> "10".

Lachlan Andrew <lachlan>
Project Member
Sun 05 Jun 2016 11:25:35 AM UTC, comment #11:

Octave 4.0.2 on Windows. 32bit MinGW zip file install.

I cannot recreate the delays like before. On a fresh start an immediate pager call took ~9 sec. Every pager call after that had a 2sec delay or less (there has always been a brief pause before displaying). Unable to recreate longer delay again, even closing and reopening octave.

Nicholas Jankowski <nrjank>
Sat 04 Jun 2016 01:00:45 PM UTC, comment #10:

Nicholas and Philip, do you still observe this?

Lachlan Andrew <lachlan>
Project Member
Sun 19 Jul 2015 06:45:05 PM UTC, comment #9:

sorry for the timelag.

I've been unable to identify any real pattern as two when it will and won't delay. It always delays on the first call to 'less'. Other than that, the things I listed in previous comments pretty much describe the situation. Repeating the command will sometimes produce a delay, sometimes not. Just now, on a fresh load I typed 'help struct' before I remembered to do a 'more off'. It delayed. I tried it again, it delayed. I tried it a third and fourth time, it came up without delay. On a fifth and sixth time, it delayed. 7th through ... 14-15th, no delay. 16th time, 20 second delay... (all of these in the GUI)

Nicholas Jankowski <nrjank>
Sun 05 Jul 2015 04:02:43 AM UTC, comment #8:

I think you said the delay seems random, but maybe there is some type of pattern. Can you detect any? I'm wondering if maybe CR-LF in "less" could be problematic. Just guessing.

Dan Sebald <sebald>
Sat 04 Jul 2015 10:24:59 PM UTC, comment #7:

default PAGER on windows build seems to be 'less'. appears there are no no other variants included with the build (more and pg suggested in the docs) included?

the only variable that seemed like it might matter is page_output_immediately (set to false by default). Setting it to 1, doesn't seem to help at all. It seemed to make other outputs display using the pager that wouldn't normally have done so (like >> a = [1 2 3 4 5 ; 1 2 3 4 5 ; 1 2 3 4 5]

caused a pause waiting for the pager. of course ,immediately afterward, [1:100]' did not.

Nicholas Jankowski <nrjank>
Sat 04 Jul 2015 08:57:54 PM UTC, comment #6:

ahh, so 'pager' the right name to use for this. I'll peek at the docs now that I found it (https://www.gnu.org/software/octave/doc/interpreter/Paging-Screen-Output.html) and see if anything there affects behavior.

the root issue not usually an issue on Windows. standard installation in C:/octave/octave-4.0.0

Nicholas Jankowski <nrjank>
Sat 04 Jul 2015 08:51:53 PM UTC, comment #5:

I can confirm this. I have seen this behavior for a long time although I haven't paid much attenton to it (I usually do not use the pager, so when this happens I interrupt the operation with Ctrl-C, type "more off" and start over).

Could it be that the pager is simply waiting until the end of the output or until the screen buffer is filled (rather than until the pager buffer is filled) ?

Philip Nienhuis <philipnienhuis>
Project Member
Sat 04 Jul 2015 08:19:33 PM UTC, comment #4:

Hmm, this is an odd bug. At first it sounded similar to a bug I'm recalling with regard to the file dialog box taking 20 seconds on Windows (I can't find it via search to see how that was resolved), but if the problem exists with the --no-gui-libs option I doubt it is the same issue.

Can you think of anything you've done during installation that might be unusual? Installing as non-root in a system directory, something like that.

Dan Sebald <sebald>
Sat 04 Jul 2015 08:09:20 PM UTC, comment #3:

ok, ran octave.exe directly from the bin folder with the --no-gui-libs, rather than the batch file in the root folder.

ran 'pkg list' right after the program opened and got the same 20-30 second delay on the output.

Nicholas Jankowski <nrjank>
Sat 04 Jul 2015 08:04:01 PM UTC, comment #2:

sorry, to clarify, the issue described in the first few paragraphs is under the normal GUI (no "--no-gui" option). 2nd to last paragraph describes running with "--no-gui".

I tried "--no-gui-libs". it closes immediately, but best as I can tell it gives an unrecognized option error. peeking in octave.bat, it doesn't seem to be setup to handle that option, unless it's supposed to just pass that forward to octave-cli.exe.

Nicholas Jankowski <nrjank>
Sat 04 Jul 2015 07:18:50 PM UTC, comment #1:

Is there such delay when operating under the GUI normally, i.e., no "--no-gui" option?

Also try the sames tests when using the "--no-gui-libs" option and report back the behavior. Thanks.

Dan Sebald <sebald>
Sat 04 Jul 2015 05:39:51 PM UTC, original submission:

Using version 4.0.0 on Windows 7, issue appears running with the GUI or with --no-gui from a windows command prompt.

With GUI: On first call to anything with a long output, there is a 20-30 second delay. I first saw this calling 'pkg list'. a second 'pkg list' appears without delay. calling a long help entry, such as "help n4sid" does the same thing. After an initial delay on each, I can go back and forth between the two without any delayed display. Calling a third long output, such as

>> [1:100]'


also creates a delay, but calling it again creates a delay almost every time. But not every time, and I can't seem to predict when it will and won't delay. thinking it might be caching something, following up with [1:200]' didn't have a delay. but then "pkg list" right afterward did...

resizing the command window seems to cause it to pause again on an initial calls to 'pkg list'.

I re-opened Octave with --no-gui from a windows command prompt. same initial delay on 'pkg list'. resizing the command prompt window caused it to delay again, but on the second call, not the first.

this is odd. have yet to verify this is not just happening to me. happy trying to recreate things if it helps. have been doing a "more off" at the start of every session to avoid all of this.

Also,
running

>> profile on; tic; help n4sid
>> toc

Elapsed time is 29.4987 seconds.

>> profile off
>> profexplore

only shows 0.111 seconds on help, even though there was a 30 second delay. (0.102 seconds to 'system')

Nicholas Jankowski <nrjank>

 

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

Attach File(s):
   
   
Comment:
   

No files currently attached

 

Depends on the following items: None found

Digest:
   bug dependencies.

 

Carbon-Copy List
  • -unavailable- added by jwe (Posted a comment)
  • -unavailable- added by jbruns (Posted a comment)
  • -unavailable- added by lostbard (Posted a comment)
  • -unavailable- added by tmacchant
  • -unavailable- added by tmacchant (Posted a comment)
  • -unavailable- added by nrjank
  • -unavailable- added by mtmiller (Updated the item)
  • -unavailable- added by lachlan (Posted a comment)
  • -unavailable- added by sebald (Posted a comment)
  • -unavailable- added by nrjank (Submitted the item)
  •  

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

    Only project members can vote.

     

    Please enter the title of George Orwell's famous dystopian book (it's a date):

     

     

    Follow 6 latest changes.

    Date Changed By Updated Field Previous Value => Replaced By
    Thu 13 Jul 2017 03:53:25 AM UTCrik5Dependencies-=>bugs #51316 is dependent
    Thu 29 Jun 2017 04:32:03 AM UTCtmacchantCarbon-Copy-=>Added -unavailable-
    Wed 28 Jun 2017 03:37:34 PM UTCnrjankCarbon-Copy-=>Added tmacchant
    Thu 17 Nov 2016 06:27:45 PM UTCmtmillerRelease4.0.2=>4.2.0
    Sun 05 Jun 2016 10:34:37 PM UTClachlanRelease4.0.0=>4.0.2
      Summaryoutput calling "more" has 20+ second delay?=>output calling "more" has 10 second delay?

    Back to the top


    Powered by Savane 3.1-cleanup1