Open Bug 1613824 Opened 5 years ago Updated 10 months ago

Apple Newsroom page takes a long time to load (30 seconds)

Categories

(Core :: Performance: Navigation, defect, P2)

Product:
Core
Component:
Performance: Navigation
Platform:
Unspecified
Android
Type:
defect

Tracking

()

Project Flags:
Performance Impact medium

People

(Reporter: yoasif, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: perf:pageload, Whiteboard: [geckoview:m76])

Attachments

(2 files)

apple.7z
8.83 MB, application/x-7z-compressed
Details
slow ODA
163.79 KB, text/plain
Details

Noticed that the progress bar took a long time to disappear when loading https://www.apple.com/newsroom/2019/11/apple-introduces-16-inch-macbook-pro-the-worlds-best-pro-notebook/

I don't know why that is, so I took a profile: https://perfht.ml/2vbdlPk

The profile is me loading the page -- I waited for the progress bar to disappear. This is quite a bit slower than other browsers on my device.

Device is a Pixel 2 with GeckoView example and WebRender enabled.

Perf folks, can you take a look?

Whiteboard: [qf] [geckoview]

We were able to reproduce this once in Geckoview, but not consistently.

There are numerous image requests that can take up to 30 seconds, as in the reporter's profile:
https://perfht.ml/3bNnYZo

Concern is that perhaps there is a networking issue causing these to be delayed.

Whiteboard: [qf] [geckoview] → [qf:p2:pageload] [geckoview]
Rank: 5
Priority: -- → P2
Whiteboard: [qf:p2:pageload] [geckoview] → [qf:p2:pageload] [geckoview:m76]
Priority: P2 → P1
Whiteboard: [qf:p2:pageload] [geckoview:m76] → [qf:p2:pageload] [geckoview:m76][geckoview:m77]
Priority: P1 → P2
Whiteboard: [qf:p2:pageload] [geckoview:m76][geckoview:m77] → [qf:p2:pageload] [geckoview:m76][geckoview:m78]
Whiteboard: [qf:p2:pageload] [geckoview:m76][geckoview:m78] → [qf:p2:pageload] [geckoview:m76]

Can you please take a look at this performance issue and see if there is a networking issue here?

Component: General → Networking
Product: GeckoView → Core
Rank: 5
Priority: P2 → --

I fail to find how to move on from the profile.
Although images are low priority, the high priority requests are finished way before.
The main thread is not busy at all.
Not proxy issue since other requests from same domain are finished way earlier.
Same reason for excluding proxy.

Could be the package coming back really late. It's hard to tell.

Could you find another pair of eyes on this, Nhi? Better with testing device.

Flags: needinfo?(nhnguyen)

Honza, does anything stand out to you in the profile?

Flags: needinfo?(nhnguyen) → needinfo?(honzab.moz)

It's impossible to diagnose networking issue from perf logs, unless there is HTTP and socket logging turned on along profile capturing. A log on its own would do too.

Flags: needinfo?(honzab.moz)

Hello Asif,
Per Comment 6, we need HTTP log to see if there's room to improve in necko.
We need to set MOZ_LOG to timestamp,rotate:200,nsHttp:5,cache2:5,nsSocketTransport:5,nsHostResolver:5 and pull out log from LOGCAT
Here's the way to set environment variable for GeckoView
https://firefox-source-docs.mozilla.org/mobile/android/geckoview/consumer/automation.html#reading-configuration-from-a-file

Flags: needinfo?(yoasif)

I need a little more help in getting this log file for you - what app do I need to use? I am not building GeckoView, so I think these instructions don't help me that much. Is there something I can reference that lets me do this via Fenix or GeckoView Example?

Hello :snorp,
Could you help to move comment 8 forward? Thanks.

Flags: needinfo?(snorp)

The configuration file will work with GeckoView Example. You need to put the config file at /data/local/tmp/org.mozilla.geckoview_example-geckoview-config.yaml

Flags: needinfo?(snorp)
Attached file apple.7z —

Log file attached. Zip didn't make the file small enough for bugzilla.

Flags: needinfo?(yoasif)
Attached file slow ODA —

Some Note:

Comment 12 shows the 10s between OnStartRequest and OnStopRequest.
However, I believe we miss some log for 0x771e6ba000.

For example,

05-29 13:05:54.781 I/Gecko   (19281): 2020-05-29 17:05:54.781568 UTC - [Parent 19281: Main Thread]: D/nsHttp nsHttpChannel::Connect [this=0x771e6ba000]
05-29 13:05:54.782 I/Gecko   (19281): 2020-05-29 17:05:54.782194 UTC - [Parent 19281: Main Thread]: D/nsHttp nsHttpChannel 0x771e6ba000 tracking resource=0, cos=0
05-29 13:05:54.782 I/Gecko   (19281): 2020-05-29 17:05:54.782206 UTC - [Parent 19281: Main Thread]: D/nsHttp nsHttpChannel 0x771e6ba000 not eligible for tail-blocking
05-29 13:05:56.127 I/Gecko   (19281): 2020-05-29 17:05:56.127757 UTC - [Parent 19281: Main Thread]: D/nsHttp nsHttpChannel::OnStartRequest [this=0x771e6ba000 request=0x77fe948450 status=0]

We should have one line log with nsHttpChannel::ConnectOnTailUnblock and to see if it's from cache or net.

Junior, can I assign this to you?

Flags: needinfo?(juhsu)
Priority: -- → P2
Whiteboard: [qf:p2:pageload] [geckoview:m76] → [qf:p2:pageload] [geckoview:m76][necko-triaged]

Sure, I'm going to take a deeper look next week. Free free to steal it if anyone is interested.

Assignee: nobody → juhsu
Flags: needinfo?(juhsu)

Reminder to myself: cut -f7- -d" " apple.log > apple.parselog to make it logan-able

The underlying nsHttpConnection is 0x771e610400 and SocketTransport is 0x771e60a670.
Networking is doing its job, here's an example.
If my calculator is correct, its 4kb/0.008seconds = 500kBps which could be a little slower than usual for that connection.

The one in comment 7 is (4 348 837 bytes) / ((72.001008 - 56.335378) * seconds) = 277.60371 kBps
The file is big, so it's not much slower.

Reporter, is it 30 seconds waiting when you got the profile?
How is the network condition? Could you use a test site to measure?

And is it slow only with the page you provide?

2020-05-29 17:05:54.628628 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport nsSocketInputStream::Read [this=0x771e60a670 count=4072]
2020-05-29 17:05:54.628644 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   calling PR_Read [count=4072]
2020-05-29 17:05:54.628666 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   PR_Read returned [n=236]
2020-05-29 17:05:54.628682 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x771e60a400 status=804b0006]
  804b0006 = STATUS_RECEIVING_FROM
2020-05-29 17:05:54.629058 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0x771e60b000 status=804b0006 progress=6108]
2020-05-29 17:05:54.629073 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::WritePipeSegment 0x771e60b000 written=236
2020-05-29 17:05:54.629087 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::ProcessData [this=0x771e60b000 count=236]
2020-05-29 17:05:54.629102 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=236]
2020-05-29 17:05:54.629118 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=236 read=236 mContentRead=5766 mContentLength=17035]
2020-05-29 17:05:54.629149 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport nsSocketInputStream::Read [this=0x771e60a670 count=3836]
2020-05-29 17:05:54.629163 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   calling PR_Read [count=3836]
2020-05-29 17:05:54.629221 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   PR_Read returned [n=1024]
2020-05-29 17:05:54.629253 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x771e60a400 status=804b0006]
  804b0006 = STATUS_RECEIVING_FROM
2020-05-29 17:05:54.630952 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0x771e60b000 status=804b0006 progress=7132]
2020-05-29 17:05:54.630967 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::WritePipeSegment 0x771e60b000 written=1024
2020-05-29 17:05:54.630982 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::ProcessData [this=0x771e60b000 count=1024]
2020-05-29 17:05:54.630997 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=1024]
2020-05-29 17:05:54.631013 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=1024 read=1024 mContentRead=6790 mContentLength=17035]
2020-05-29 17:05:54.631046 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport nsSocketInputStream::Read [this=0x771e60a670 count=2812]
2020-05-29 17:05:54.631061 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   calling PR_Read [count=2812]
2020-05-29 17:05:54.631115 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   PR_Read returned [n=1024]
2020-05-29 17:05:54.631133 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x771e60a400 status=804b0006]
  804b0006 = STATUS_RECEIVING_FROM
2020-05-29 17:05:54.632788 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0x771e60b000 status=804b0006 progress=8156]
2020-05-29 17:05:54.632804 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::WritePipeSegment 0x771e60b000 written=1024
2020-05-29 17:05:54.632819 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::ProcessData [this=0x771e60b000 count=1024]
2020-05-29 17:05:54.632835 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=1024]
2020-05-29 17:05:54.632851 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=1024 read=1024 mContentRead=7814 mContentLength=17035]
2020-05-29 17:05:54.632885 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport nsSocketInputStream::Read [this=0x771e60a670 count=1788]
2020-05-29 17:05:54.632900 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   calling PR_Read [count=1788]
2020-05-29 17:05:54.632954 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   PR_Read returned [n=1024]
2020-05-29 17:05:54.632971 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x771e60a400 status=804b0006]
  804b0006 = STATUS_RECEIVING_FROM
2020-05-29 17:05:54.634538 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0x771e60b000 status=804b0006 progress=9180]
2020-05-29 17:05:54.634556 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::WritePipeSegment 0x771e60b000 written=1024
2020-05-29 17:05:54.634571 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::ProcessData [this=0x771e60b000 count=1024]
2020-05-29 17:05:54.634586 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=1024]
2020-05-29 17:05:54.634602 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=1024 read=1024 mContentRead=8838 mContentLength=17035]
2020-05-29 17:05:54.634635 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport nsSocketInputStream::Read [this=0x771e60a670 count=764]
2020-05-29 17:05:54.634649 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   calling PR_Read [count=764]
2020-05-29 17:05:54.634701 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   PR_Read returned [n=764]
2020-05-29 17:05:54.634720 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x771e60a400 status=804b0006]
  804b0006 = STATUS_RECEIVING_FROM
2020-05-29 17:05:54.635858 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0x771e60b000 status=804b0006 progress=9944]
2020-05-29 17:05:54.635905 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::WritePipeSegment 0x771e60b000 written=764
2020-05-29 17:05:54.635920 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::ProcessData [this=0x771e60b000 count=764]
2020-05-29 17:05:54.635934 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=764]
2020-05-29 17:05:54.635950 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsHttp nsHttpTransaction::HandleContent [this=0x771e60b000 count=764 read=764 mContentRead=9602 mContentLength=17035]
2020-05-29 17:05:54.635989 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: V/nsHttp nsHttpConnection::OnSocketReadable 0x771e610400 trans->ws rv=0 n=4072 socketin=0
2020-05-29 17:05:54.636022 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport nsSocketInputStream::Read [this=0x771e60a670 count=9]
2020-05-29 17:05:54.636038 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   calling PR_Read [count=9]
2020-05-29 17:05:54.636060 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: D/nsSocketTransport   PR_Read returned [n=9]
2020-05-29 17:05:54.636077 UTC - [Parent 19281: Unnamed thread 0x77fe9469b0]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x771e60a400 status=804b0006]
  804b0006 = STATUS_RECEIVING_FROM
Flags: needinfo?(yoasif)

Reporter, is it 30 seconds waiting when you got the profile?

It was, but as of now I can no longer reproduce this issue.

How is the network condition? Could you use a test site to measure?

Speedtest.net shows 278Mbps down with a 4ms ping.

And is it slow only with the page you provide?

That is what I noticed - I don't see anything too weird elsewhere.

Flags: needinfo?(yoasif)

Turn back to gecko view given the log in comment 17 doesn't show necko is blocking 30 seconds.
The log shows the whole network activities take around 10 seconds, doing its job constantly.

Assignee: juhsu → nobody
Component: Networking → General
Priority: P2 → --
Product: Core → GeckoView
Whiteboard: [qf:p2:pageload] [geckoview:m76][necko-triaged] → [qf:p2:pageload] [geckoview:m76]

Maybe one more question:
Did the page show words only in the 30 seconds hang? Or blank for 30 seconds?

Flags: needinfo?(yoasif)

No, it looked like it was loaded (did not scroll, so I'm not sure about this) with images, but the progress bar did not go away. Certainly the first screen was loaded.

Flags: needinfo?(yoasif)

Thanks. (In reply to Emily Toop (:fluffyemily) from comment #3)

Can you please take a look at this performance issue and see if there is a networking issue here?

Thanks, Asif. I would say it's not a networking issue for now.

Component: General → DOM: Navigation
Product: GeckoView → Core

I don't know how this ended up to DOM: Navigation.
Moving to Core: Performance to get some more analysis what is happening here.

Component: DOM: Navigation → Performance
Performance Impact: --- → P2
Keywords: perf:pageload
Whiteboard: [qf:p2:pageload] [geckoview:m76] → [geckoview:m76]
Priority: -- → P2
Severity: normal → S3
Blocks: perf-android
Component: Performance: General → Performance: Navigation
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: