ultra slow os.Exec

[miha.v...@gmail.com]

Hey,

I'm running windows cli exe on linux via wine using os.Exec command.. this takes 28s to complete.

If I run the same command via linux cli it takes 2s to complete, if I run the same command via php's exec it also takes about 2 seconds to complete.

== linux cli ==

time WINEDEBUG=err-all,fixme-all WINEARCH=win32 /opt/wine-staging/bin/wine cmd.exe /c help

....

real    0m1,366s
user    0m0,002s
sys    0m0,225s

== php ==

cat t.php
<?php
$out=array();

exec('WINEDEBUG=err-all,fixme-all WINEARCH=win32 /opt/wine-staging/bin/wine cmd.exe /c help', $out);

var_dump($out);

.....

real    0m1,427s
user    0m0,035s
sys    0m0,216s

==go exec==

func main() {
    now := time.Now()
    ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
    defer cancel()
    cmd := exec.CommandContext(ctx, "/opt/wine-staging/bin/wine", "cmd", "/c", "help")
    cmd.Env = []string{"WINEDEBUG=err-all,fixme-all", "WINEARCH=win32"}
    output, err := cmd.CombinedOutput()
    if err != nil {
        fmt.Println(err)
    }
    fmt.Println(string(output))
    fmt.Println(time.Now().Sub(now))
}

time bin/osexec

real    0m39,915s
user    0m17,062s
sys    0m0,195s

* I have tried to set stdin and std out directly to the one from os (no difference)

* I have replaced cmd.CombinedOutput with cmd.Run() (no difference)

go version
go version go1.13.3 linux/amd64

I'm totally clueless on what's going on.

BR,

Miha

[Ian Lance Taylor]

How long does it take to just run the wine command from the shell?

My first guess would certainly be that the problem is in wine, not in
Go's os/exec package. Starting up a Windows emulator has to take a
certain amount of time.

Ian

[Robert Engels]

I think the point the OP is making is that when he runs the command from the Linux command line it completes in 2 sec - so the Wine startup time should not be the issue.

>--
>You received this message because you are subscribed to the Google Groups "golang-nuts" group.
>To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
>To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAOyqgcXJZy61dX_UetsKY0r%3DNMcoBcE4sCuFZVzvvPme%3DjTTDg%40mail.gmail.com.

[miha.v...@gmail.com]

Robert is right, all 3 examples are the same (they execute the same command with wine being set up and then teared down again). wine itself is not an issue. It's go's exec that does something extremely funny.

BR,

Miha

>To unsubscribe from this group and stop receiving emails from it, send an email to golan...@googlegroups.com.

[Ian Lance Taylor]

On Tue, Nov 19, 2019 at 7:29 AM <miha.v...@gmail.com> wrote:
>
> Robert is right, all 3 examples are the same (they execute the same command with wine being set up and then teared down again). wine itself is not an issue. It's go's exec that does something extremely funny.

Sorry, I misread the original note. But if I'm reading it correctly
now, I find these results pretty hard to believe. Can anybody else
replicate them?

Ian

> To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/037e16e2-158a-4cf7-8a5f-8b940d55e64a%40googlegroups.com.

[Robert Engels]

I am guessing - because it is close to 30 secs (which sounds a lot like a timeout value) - that there is some problem in hand-off with the file descriptors and the descriptor is getting locked, causing some sort of timeout.

If it was "any exe" I'm sure someone would of reported it before. It should be trivial to write a test. I'll be back...

>To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAOyqgcXR3ADH6J28wmY7vneHVnNRpGf0yia8aAyUdSrB62qwQg%40mail.gmail.com.

[Robert Engels]

>To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/847534479.3807.1574182478713%40wamui-cheeto.atl.sa.earthlink.net.

Doesn't seem to happen with a exec of "/usr/bin/date" so it is most likely something wine+Go specific.

[miha.v...@gmail.com]

> Doesn't seem to happen with a exec of "/usr/bin/date" so it is most likely something wine+Go specific.

Yeah, I did try catting the file and it was fast enough. So you are probably right.

Whats interesting is if I do it indirectly via shell script (then this is only 5 times slower not 28): But still too slow. Hell PHP can't be faster at this than Go.

cat /tmp/test
#!/bin/sh

WINEDEBUG=err-all,fixme-all WINEARCH=win32 /opt/wine-staging/bin/wine cmd.exe /c help

== go ==

func main() {
    now := time.Now()
    ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
    defer cancel()

    cmd := exec.CommandContext(ctx, "/tmp/test")
    //cmd := exec.CommandContext(ctx, "/opt/wine-staging/bin/wine", "cmd", "/c", "help")
    //cmd.Env = []string{"WINEDEBUG=err-all,fixme-all", "WINEARCH=win32"}

    output, err := cmd.CombinedOutput()
    if err != nil {
        fmt.Println(err)
    }
    fmt.Println(string(output))
    fmt.Println(time.Now().Sub(now))
}

time bin/osexec

real    0m5,256s
user    0m0,015s
sys    0m0,221s

BR,

Miha

>>> To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/037e16e2-158a-4cf7-8a5f-8b940d55e64a%40googlegroups.com.
>>
>>--
>>You received this message because you are subscribed to the Google Groups "golang-nuts" group.

>>To unsubscribe from this group and stop receiving emails from it, send an email to golan...@googlegroups.com.

>>To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAOyqgcXR3ADH6J28wmY7vneHVnNRpGf0yia8aAyUdSrB62qwQg%40mail.gmail.com.
>
>--
>You received this message because you are subscribed to the Google Groups "golang-nuts" group.

>To unsubscribe from this group and stop receiving emails from it, send an email to golan...@googlegroups.com.

[Ian Lance Taylor]

On Tue, Nov 19, 2019 at 11:45 AM <miha.v...@gmail.com> wrote:
>
> > Doesn't seem to happen with a exec of "/usr/bin/date" so it is most likely something wine+Go specific.
> Yeah, I did try catting the file and it was fast enough. So you are probably right.
>
> Whats interesting is if I do it indirectly via shell script (then this is only 5 times slower not 28): But still too slow. Hell PHP can't be faster at this than Go.

Use strace -f to see what the Go program is doing.

Ian

[miha.v...@gmail.com]

The first wait is on read, the 2nd on futex

[pid 20441] read(5, "\0\0\0@\0\0\0\0\20\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 64) = 64
[pid 20441] rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 ALRM CHLD IO], NULL, 8) = 0
[pid 20441] rt_sigprocmask(SIG_BLOCK, [HUP INT USR1 USR2 ALRM CHLD IO], [HUP INT USR1 USR2 ALRM CHLD IO], 8) = 0
[pid 20441] rt_sigprocmask(SIG_BLOCK, [HUP INT USR1 USR2 ALRM CHLD IO], [HUP INT USR1 USR2 ALRM CHLD IO], 8) = 0
[pid 20441] writev(3, [{iov_base="\34\0\0\0000\0\0\0\0\0\0\0\2\0\0\0\250r\204\377\0\0\0\0\0ty\270\377\377\377\377"..., iov_len=64}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=40}, {iov_base="\1\0\0\0\20\0\0\0", iov_len=8}], 3) = 112
[pid 20441] read(5, "\3\1\0\0\0\0\0\0\330\2656\374w\237\325\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 64) = 64
[pid 20441] rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 ALRM CHLD IO], NULL, 8) = 0
[pid 20441] rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 USR2 ALRM CHLD IO], NULL, 8) = 0
[pid 20441] read(7,


 <unfinished ...>
[pid 20437] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out)
[pid 20437] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 20437] futex(0x59fb70, FUTEX_WAIT_PRIVATE, 0, {tv_sec=60, tv_nsec=0}

BR,

Miha

[Robert Engels]

You should include -r to show the relative time stamps. This would be helpful. 

On Nov 20, 2019, at 1:58 AM, miha.v...@gmail.com wrote:



--

You received this message because you are subscribed to the Google Groups "golang-nuts" group.

To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/c12d38c3-618f-499a-bcaf-d2862272cfed%40googlegroups.com.

[Ian Lance Taylor]

On Wed, Nov 20, 2019 at 5:09 AM Robert Engels <ren...@ix.netcom.com> wrote:
>
> You should include -r to show the relative time stamps. This would be helpful.

Also tell us what the different processes are. I'm guessing that in
the fragment above 20441 is wine itself? What is file descriptor 7?

Perhaps you could put the whole trace online somewhere so that we can see it.

Ian

> To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/9553B4A3-0589-4D3B-A330-7AE867E2A3C5%40ix.netcom.com.

[Damir Ivankovic]

Hi,

I'm having same or similar issue here. 

Did anyone get to the root cause ot the problem here?

I'm using exec.Command to start external process. On Windows 10 and 11 it runs quickly (under 1 second), but on Windows 7 (without SP1) it takes about 9 seconds to start external exe or script. It is not issue with external process since I tried it with different executables and bat scripts and problem is always the same on the same machine, and there is not problem on others.

BR

Damir