Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-27 Thread Michael Andersen
> > If it's true that some goroutines are simply looping, then the only > way to get their current PC is to crash the program with SIGQUIT and > look at the stack trace. The runtime doesn't have any way to ask a > goroutine what the currently executing PC is. I suggest using pstack to capture t

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-27 Thread Robert Engels
I suggest using pstack to capture the stacks of all threads of you can. Because it is external ut is not subject to the stopping bias of the internal go facilities. > On Aug 27, 2019, at 9:05 AM, Ian Lance Taylor wrote: > >> On Mon, Aug 26, 2019 at 2:12 PM Michael Andersen >> wrote: >> >>

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-27 Thread Ian Lance Taylor
On Mon, Aug 26, 2019 at 2:12 PM Michael Andersen wrote: > > I was concerned that perhaps the stacks that I dumped after the scheduling > stall did not reflect the actual PC's of the goroutines during the stall, so > I modified schedtrace to dump out g.sched.pc and g.m.vdsoPC for each G > curren

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-26 Thread Michael Andersen
Incidentally, it just happened again without involving the GC stop the world, where all 8 P's were running and had the same program counters for 4 seconds. They are the same as those in the previous email. On Mon, Aug 26, 2019 at 2:11 PM Michael Andersen wrote: > Hi > > I was concerned that perh

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-26 Thread Michael Andersen
Hi I was concerned that perhaps the stacks that I dumped after the scheduling stall did not reflect the actual PC's of the goroutines during the stall, so I modified schedtrace to dump out g.sched.pc and g.m.vdsoPC for each G currently on the P at the time schedtrace prints. It just occurred agai

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-24 Thread Michael Andersen
> > > > Out of interest what OS? > > Is the machine virtualised? > Yes, this on EC2, on m5.2xlarge (which are nitro instances with vDSO-supporting clock). I am running Linux 4.9.0 > Also, are you running a kernel with VDSO enabled? With VDSO, > `time.Now` should not be making any system calls.

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-24 Thread Ian Lance Taylor
On Sat, Aug 24, 2019 at 1:28 AM Steven Hartland wrote: > > Out of interest what OS? > Is the machine virtualised? > > You might want to try doing an OS syscall trace to see if it’s stuck in an OS > call for some reason. Also, are you running a kernel with VDSO enabled? With VDSO, `time.Now` sho

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-24 Thread Steven Hartland
Out of interest what OS? Is the machine virtualised? You might want to try doing an OS syscall trace to see if it’s stuck in an OS call for some reason. Regards Steve On Sat, 24 Aug 2019 at 03:37, Michael Andersen wrote: > This is built with go 1.12.5, incidentally, but I have seen this on

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Michael Andersen
This is built with go 1.12.5, incidentally, but I have seen this on several go versions spanning several months. On Fri, Aug 23, 2019 at 7:36 PM Michael Andersen wrote: > Ok, so I have more information, and it's not what I would expect. > > I added scheddetail=1,schedtrace=2000 so that I had a l

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Michael Andersen
Ok, so I have more information, and it's not what I would expect. I added scheddetail=1,schedtrace=2000 so that I had a list of which M's and G's were on the P's during the 5 seconds that scheduling stalled. I added a sentinel goroutine that sleeps 1 second in a loop and panics if the sleep takes

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Ian Lance Taylor
On Fri, Aug 23, 2019 at 2:30 PM Michael Andersen wrote: > > Are you suggesting that there might be enough unpreemtable goroutines to fill > all the P's? I do have several cgo goroutines sitting in syscalls, but my > understanding was that the scheduler would "preempt" that by moving the M off >

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Michael Andersen
On Fri, Aug 23, 2019 at 2:12 PM Robert Engels wrote: > If you write an long running non pre-emptable all go routines are > effected. > > Yeah, I've come across the case before where GC would begin a stop the world but get stuck waiting for a non-preemtable goroutine. I don't think that's happenin

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Robert Engels
If you write an long running non pre-emptable all go routines are effected. > On Aug 23, 2019, at 4:03 PM, Michael Andersen wrote: > > > >> On Fri, Aug 23, 2019 at 1:23 PM Ronny Bangsund >> wrote: >>> On Friday, August 23, 2019 at 5:58:44 PM UTC+2, Michael Andersen wrote: >>> It can take a

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Michael Andersen
On Fri, Aug 23, 2019 at 1:23 PM Ronny Bangsund wrote: > On Friday, August 23, 2019 at 5:58:44 PM UTC+2, Michael Andersen wrote: >> >> It can take a while to reproduce, so it might be a week or so before I >> have the results. >> > Can you think of ways to cause the same memory pressure quicker? M

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Ronny Bangsund
On Friday, August 23, 2019 at 5:58:44 PM UTC+2, Michael Andersen wrote: > > It can take a while to reproduce, so it might be a week or so before I > have the results. > Can you think of ways to cause the same memory pressure quicker? Mocking data, running the functions the number of times they wo

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-23 Thread Michael Andersen
Thanks, that's a good idea. I'll add that in. It can take a while to reproduce, so it might be a week or so before I have the results. On Thu, Aug 22, 2019 at 10:23 PM Ian Lance Taylor wrote: > On Thu, Aug 22, 2019 at 5:09 PM wrote: > > > > I have a fairly complex program that has about 150 gor

Re: [go-nuts] Goroutine scheduled 10 seconds too late

2019-08-22 Thread Ian Lance Taylor
On Thu, Aug 22, 2019 at 5:09 PM wrote: > > I have a fairly complex program that has about 150 goroutines servicing > requests. Some requests go out to cgo, which does some network IO. There is > one goroutine that is responsible for a heartbeat (etcd keepalive) and > sometimes (~every two weeks

[go-nuts] Goroutine scheduled 10 seconds too late

2019-08-22 Thread michael
I have a fairly complex program that has about 150 goroutines servicing requests. Some requests go out to cgo, which does some network IO. There is one goroutine that is responsible for a heartbeat (etcd keepalive) and sometimes (~every two weeks) this goroutine doesn't get scheduled for long p