1124717 - After network problem Firefox stop loading any sites and "Socket Thread" process consume 100% CPU

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Mikhail]

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.12 Safari/537.36

Steps to reproduce:

Don't know


Actual results:

After network problem Firefox stop loading any sites and "Socket Thread" process consume 100% CPU

Comment 1

[Mikhail]

stack trace

(gdb) thread apply all bt

Thread 1 (process 10639):
#0  0x00007f89b0d8c3e0 in mozilla::net::nsHttpTransaction::ReadRequestSegment(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*) () from /home/mikhail/Downloads/firefox/libxul.so
#1  0x00007f89b0c8065b in nsBufferedInputStream::ReadSegments(tag_nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) ()
   from /home/mikhail/Downloads/firefox/libxul.so
#2  0x00007f89b0d8c2c4 in mozilla::net::nsHttpTransaction::ReadSegments(mozilla::net::nsAHttpSegmentReader*, unsigned int, unsigned int*) () from /home/mikhail/Downloads/firefox/libxul.so
#3  0x00007f89b0d51dbd in mozilla::net::Http2Stream::ReadSegments(mozilla::net::nsAHttpSegmentReader*, unsigned int, unsigned int*) () from /home/mikhail/Downloads/firefox/libxul.so
#4  0x00007f89b0d59abd in mozilla::net::Http2Session::ReadSegments(mozilla::net::nsAHttpSegmentReader*, unsigned int, unsigned int*) () from /home/mikhail/Downloads/firefox/libxul.so
#5  0x00007f89b0d7e9cf in mozilla::net::nsHttpConnection::OnSocketWritable() () from /home/mikhail/Downloads/firefox/libxul.so
#6  0x00007f89b0d7ec06 in mozilla::net::nsHttpConnection::OnOutputStreamReady(nsIAsyncOutputStream*) () from /home/mikhail/Downloads/firefox/libxul.so
#7  0x00007f89b0c986ef in nsSocketOutputStream::OnSocketReady(tag_nsresult) () from /home/mikhail/Downloads/firefox/libxul.so
#8  0x00007f89b0c98fe9 in nsSocketTransport::OnSocketReady(PRFileDesc*, short) () from /home/mikhail/Downloads/firefox/libxul.so
#9  0x00007f89b0c9d978 in nsSocketTransportService::DoPollIteration(bool) () from /home/mikhail/Downloads/firefox/libxul.so
#10 0x00007f89b0c9dd1d in nsSocketTransportService::Run() () from /home/mikhail/Downloads/firefox/libxul.so
#11 0x00007f89b094f976 in nsThread::ProcessNextEvent(bool, bool*) () from /home/mikhail/Downloads/firefox/libxul.so
#12 0x00007f89b095752e in NS_ProcessNextEvent(nsIThread*, bool) () from /home/mikhail/Downloads/firefox/libxul.so
#13 0x00007f89b0e3a936 in mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) () from /home/mikhail/Downloads/firefox/libxul.so
#14 0x00007f89b0e30c02 in MessageLoop::Run() () from /home/mikhail/Downloads/firefox/libxul.so
#15 0x00007f89b0c395df in nsThread::ThreadFunc(void*) () from /home/mikhail/Downloads/firefox/libxul.so
#16 0x00007f89b59eb945 in _pt_root () from /home/mikhail/Downloads/firefox/libnspr4.so
#17 0x00007f89b6e5152a in start_thread (arg=0x7f899b6fe700) at pthread_create.c:310
#18 0x00007f89b5f5379d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb)

Comment 2

[Mikhail]

Attachment: htop screenshot

Comment 3

[Mikhail]

Attachment: full firefox trace

Comment 4

[Mikhail]

While the browser is still running but consumes CPU what information would be helpful?

Comment 5

[Mikhail]

Attachment: firefox strace

Comment 6

[Patrick McManus [:mcmanus]]

you could put a breakpoint on the line in stack 4 and see if it keeps ending up spinning past this, and if so what it is returning.

Comment 7

[Patrick McManus [:mcmanus]]

when you say "after network problem" what are you referring to?

Comment 8

[Mikhail]

(In reply to Patrick McManus [:mcmanus] from comment #6)
> you could put a breakpoint on the line in stack 4 and see if it keeps ending
> up spinning past this, and if so what it is returning.
You means set breakpoint on this line?
#4  0x00007f89b0d59abd in mozilla::net::Http2Session::ReadSegments(mozilla::net::nsAHttpSegmentReader*, unsigned int, unsigned int*) () from /home/mikhail/Downloads/firefox/libxul.so
and sure that we are in cycle?


(In reply to Patrick McManus [:mcmanus] from comment #7)
> when you say "after network problem" what are you referring to?
I forgot to recharge the internet account. When this happens provider puts his stub on all sites. And seems at this time browser tries to update itself.

Comment 9

[Patrick McManus [:mcmanus]]

(In reply to Mikhail from comment #8)
> (In reply to Patrick McManus [:mcmanus] from comment #6)
> > you could put a breakpoint on the line in stack 4 and see if it keeps ending
> > up spinning past this, and if so what it is returning.
> You means set breakpoint on this line?
> #4  0x00007f89b0d59abd in
> mozilla::net::Http2Session::ReadSegments(mozilla::net::nsAHttpSegmentReader*,
> unsigned int, unsigned int*) () from
> /home/mikhail/Downloads/firefox/libxul.so
> and sure that we are in cycle?
>

yes.. and if you can stand it just hit "next" through the http2stream and http2session readsegments functions.. printing out rv as needed. thanks.

can you make this happen after a restart? if you could then an http log 
https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging would be much more helpful.

Comment 10

[Mikhail]

(In reply to Patrick McManus [:mcmanus] from comment #9)
> yes.. and if you can stand it just hit "next" through the http2stream and
> http2session readsegments functions.. printing out rv as needed. thanks.
> 

(gdb) c
Continuing.
^C
Program received signal SIGINT, Interrupt.
0x00007f89b0d8c3e0 in mozilla::net::nsHttpTransaction::ReadRequestSegment(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*) () from /home/mikhail/Downloads/firefox/libxul.so
(gdb) s
Single stepping until exit from function _ZN7mozilla3net17nsHttpTransaction18ReadRequestSegmentEP14nsIInputStreamPvPKcjjPj,
which has no line number information.
0x00007f89b0c8065b in nsBufferedInputStream::ReadSegments(tag_nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) ()
   from /home/mikhail/Downloads/firefox/libxul.so
(gdb) s
Single stepping until exit from function _ZN21nsBufferedInputStream12ReadSegmentsEPF12tag_nsresultP14nsIInputStreamPvPKcjjPjES3_jS6_,
which has no line number information.
0x00007f89b0c80668 in nsBufferedInputStream::ReadSegments(tag_nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) ()
   from /home/mikhail/Downloads/firefox/libxul.so
ptrace: No such process.
(gdb) s
Single stepping until exit from function _ZN21nsBufferedInputStream12ReadSegmentsEPF12tag_nsresultP14nsIInputStreamPvPKcjjPjES3_jS6_,
which has no line number information.
0x00007f89b0c80668 in nsBufferedInputStream::ReadSegments(tag_nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) ()
   from /home/mikhail/Downloads/firefox/libxul.so
ptrace: No such process.
(gdb) s
Single stepping until exit from function _ZN21nsBufferedInputStream12ReadSegmentsEPF12tag_nsresultP14nsIInputStreamPvPKcjjPjES3_jS6_,
which has no line number information.
0x00007f89b0c80668 in nsBufferedInputStream::ReadSegments(tag_nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) ()
   from /home/mikhail/Downloads/firefox/libxul.so
ptrace: No such process.
(gdb) s
Single stepping until exit from function _ZN21nsBufferedInputStream12ReadSegmentsEPF12tag_nsresultP14nsIInputStreamPvPKcjjPjES3_jS6_,
which has no line number information.
0x00007f89b0c80668 in nsBufferedInputStream::ReadSegments(tag_nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*) ()
   from /home/mikhail/Downloads/firefox/libxul.so
ptrace: No such process.
(gdb) 
Program terminated with signal SIGTRAP, Trace/breakpoint trap.
The program no longer exists.

The program is not being run.
(gdb) q


sorry it crashed :(




> can you make this happen after a restart? if you could then an http log 
> https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
> would be much more helpful.

it would be usefull only if i could reproduce this again.

Comment 11

[Mikhail]

Attachment: firefox tty output

Comment 12

[Vladan Djeric (:vladan)]

I ran into the same issue (can't navigate, high CPU usage) with 32-bit Nightly 38 on Win7.
Stack: http://pastebin.mozilla.org/8365924

Comment 14

[Patrick McManus [:mcmanus]]

mikhail - thanks for a useful report. I was able to make the same thing happen by having an upload stream get queued over the max concurrency limit of h2 or spdy.

patch and test too follow

Comment 15

[Patrick McManus [:mcmanus]]

Attachment: MozReview Request: bz://1124717/mcmanus

/r/3005 - bug 1124717 - 1/4 h2/spdy fix spin when queuing post/put request over concurrent limit r=hurley
/r/3007 - bug 1124717 - 2/4 update CI to node-http2 3.1.0 to fix flow control issue r=hurley
/r/3009 - bug 1124717 - 3/4 make h2/spdy default peer max concurrent setting configurable r=hurley
/r/3011 - bug 1124717 - 4/4 test r=hurley

Pull down these commits:

hg pull review -r 812395cc0e3ed08aa5051683021caabd181cfcd2

Comment 16

[Gregory Szorc [:gps]]

https://reviewboard.mozilla.org/r/3003/#review2327

Pro tip: with MozReview, you don't need to record part numbers in the commit message because it is implicitly part of the repository data! MozReview will always display commits in the order they exist in the repository (unlike Bugzilla, which is patch file based and doesn't have access to this data).

Comment 17

[Patrick McManus [:mcmanus]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5a1e54cec3cb

Comment 18

[u408661]

Comment on attachment 8554943 [details]
MozReview Request: bz://1124717/mcmanus

https://reviewboard.mozilla.org/r/3003/#review2399

LGTM

Comment 19

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7b7d437f2adf
https://hg.mozilla.org/integration/mozilla-inbound/rev/edee665f5e63
https://hg.mozilla.org/integration/mozilla-inbound/rev/141093a1f646
https://hg.mozilla.org/integration/mozilla-inbound/rev/21cc8ac2fb4c

Comment 20

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7b7d437f2adf
https://hg.mozilla.org/mozilla-central/rev/edee665f5e63
https://hg.mozilla.org/mozilla-central/rev/141093a1f646
https://hg.mozilla.org/mozilla-central/rev/21cc8ac2fb4c

Comment 22

[Patrick McManus [:mcmanus]]

Attachment: MozReview Request: bug 1124717 - 3/4 make h2/spdy default peer max concurrent setting configurable r=hurley

Comment 23

[Patrick McManus [:mcmanus]]

Attachment: MozReview Request: bug 1124717 - 4/4 test r=hurley

Comment 24

[Patrick McManus [:mcmanus]]

Attachment: MozReview Request: bug 1124717 - 1/4 h2/spdy fix spin when queuing post/put request over concurrent limit r=hurley

Comment 25

[Patrick McManus [:mcmanus]]

Attachment: MozReview Request: bug 1124717 - 2/4 update CI to node-http2 3.1.0 to fix flow control issue r=hurley