At the start of the thread, you said "if I compile and run this simple
program ..."
Does the problem no longer reproduce with that?
On Monday, 11 April 2022 at 22:59:55 UTC+1 scorr...@gmail.com wrote:
> I tried with a more complex application and already got constant 100% CPU
> usage twice.
>
> When I attach strace I see the same as with the minimal demo but with much
> more frecuency:
>
> [pid 42659] 23:36:49.035120 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035133 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035145 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035158 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035170 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035182 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035195 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035207 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035219 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035232 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035244 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035257 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035269 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035281 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
> [pid 42659] 23:36:49.035293 epoll_pwait(3, [], 128, 0, NULL,
> 140341803388040) = 0
> [pid 42659] 23:36:49.035306 epoll_pwait(3, [], 128, 0, NULL,
> 18704162493558) = 0
>
> The program is too large to post here. I have tested it with go race and
> it doesn't run into any problem. Any idea of what to look for?
>
> Thank you!
>
> El lunes, 11 de abril de 2022 a las 17:08:40 UTC+2, Santiago Corredoira
> escribió:
>
>> I tried with the stripped tmp version of "go run" and after a while I was
>> able to reproduce it too. It definitely took me more time but probably is
>> just random.
>>
>> I tried "$ GODEBUG=asyncpreemptoff=1 ./test" and I kept seeing the the
>> calls every 10ms. Is this expected to happen?
>>
>> I compiled the test with "$ go1.16 build test.go" and I tried hard to
>> reproduce it but I couldn't. It is very strange because this behaviour was
>> introduced in Go 1.14 and I only see it in Go 1.17. Also asyncpreemptoff=1
>> seems to make no difference.
>>
>> I am going to work again with Go 1.18 by default to see if I get the 100%
>> CPU usage.
>>
>> El lunes, 11 de abril de 2022 a las 13:28:48 UTC+2, Brian Candler
>> escribió:
>>
>>> On Monday, 11 April 2022 at 09:26:28 UTC+1 scorr...@gmail.com wrote:
>>>
>>>> and the output keeps growing like that with every new curl request
>>>> until eventually it starts constantly printing output like this:
>>>>
>>>>>
>>>>> [pid 143818] 10:02:22.697120 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.707609 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.718125 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.728753 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.739195 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.749618 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.760160 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.770669 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.781137 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.791581 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.802060 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.812540 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.822981 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>> [pid 143818] 10:02:22.833468 nanosleep({tv_sec=0, tv_nsec=10000000},
>>>>> NULL) = 0
>>>>>
>>>>>
>>> That is normal, I believe, for a process with multiple runnable
>>> goroutines - one alarm/wakeup call every 10ms.
>>>
>>> What is odd is the 100% CPU utilisation. Can you attach an strace when
>>> that happens?
>>>
>>> As for the binary produced by "go run" - use "ps" to see where it is.
>>> For example:
>>>
>>> ==> sleepy.go <==
>>> package main
>>>
>>> import (
>>> "sync"
>>> "time"
>>> )
>>>
>>> func main() {
>>> var wg sync.WaitGroup
>>> wg.Add(1)
>>> go func() {
>>> time.Sleep(30 * time.Second)
>>> wg.Done()
>>> }()
>>> wg.Wait()
>>> }
>>> ==> end <==
>>>
>>> $ go run sleepy.go
>>>
>>> ... in another window ...
>>> $ ps auxwww | grep sleepy
>>> ubuntu 17743 0.0 0.1 1237424 12428 pts/1 Sl+ 11:23 0:00 go
>>> run sleepy.go
>>> ubuntu 17782 0.0 0.0 702468 1052 pts/1 Sl+ 11:23 0:00
>>> /tmp/go-build2834561198/b001/exe/sleepy
>>>
>>> You can 'cp' it somewhere to keep it safe.
>>>
>>> If I compare this with the output of "go build sleepy.go", I see that
>>> the "go build" version is larger and unstripped:
>>>
>>> $ cp /tmp/go-build2834561198/b001/exe/sleepy sleepy-run
>>> $ file sleepy-run
>>> sleepy-run: ELF 64-bit LSB executable, x86-64, version 1 (SYSV),
>>> statically linked, stripped
>>> $ go build sleepy.go
>>> $ file sleepy
>>> sleepy: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically
>>> linked, not stripped
>>>
>>> Then "strip sleepy" gives me a binary which is almost, but not quite,
>>> the same size as the one from "go run". So that gives you another way to
>>> try to reproduce the problem - although if the difference is just between
>>> stripped and unstripped, then it's most likely some sort of edge timing
>>> case.
>>>
>>
--
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+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/golang-nuts/48302bb4-650d-4329-b9c1-77b6aaaf8f97n%40googlegroups.com.
