Processing time increased for "Start to measure Page Load" in 28.2.0

manjunathpremkumar commented 1 year ago

Have you read the documentation?

[X] Yes, I've read the how to make a reproducable bug guide
[ ] Yes, I've read the how to debug my script guide

URL

https://fly4.emirates.com

What are you trying to accomplish

in 26.1.0 , below is log output where "Start to measure Page Load" process execution time was at 90-95 seconds for the page I am testing. Whereas in 28.1.0 for the same page I am seeing 140-145 seconds Environment details of 26.1.0, Rhel 7.9, Python 2.7, Docker version 1.8 Environment details of 28.2.0, RHEL 8.7, Python 3.6. Podman version 4.2

Please find the logs extract for sitespeed version 26.1.0

0 | [2023-07-18 08:03:42] INFO: Navigating to url https://fly4.emirates.com iteration 1 -- | -- 94 | [2023-07-18 08:05:16] INFO: Start to measure URP_Page_Load 28 | [2023-07-18 08:05:44] INFO: Take after page complete check screenshot 1 | [2023-07-18 08:05:45] INFO: Take cumulative layout shift screenshot 1 | [2023-07-18 08:05:46] INFO: No element attached to the entry in largest-contentful-paint 0 | [2023-07-18 08:05:46] INFO: Take largest contentful paint screenshot 3 | [2023-07-18 08:05:49] INFO: Get visual metrics from the video

logs extract for sitespeed version 28.2.0,

0 | [2023-08-18 04:03:29] INFO: Navigating to url https://fly4.emirates.com iteration 1 -- | -- 141 | [2023-08-18 04:05:50] INFO: Start to measure URP_Page_Load 30 | [2023-08-18 04:06:20] INFO: Take after page complete check screenshot 1 | [2023-08-18 04:06:21] INFO: Take cumulative layout shift screenshot 1 | [2023-08-18 04:06:22] INFO: No element attached to the entry in largest-contentful-paint 0 | [2023-08-18 04:06:22] INFO: Take largest contentful paint screenshot 3 | [2023-08-18 04:06:25] INFO: Get visual metrics from the video

What browser did you use?

Chrome

How to reproduce

We are using scripted journey

Log output

log extract from 26.1.0,

0   [2023-07-18 08:03:42] INFO: Navigating to url https://fly4.emirates.com iteration 1
94  [2023-07-18 08:05:16] INFO: Start to measure URP_Page_Load
28  [2023-07-18 08:05:44] INFO: Take after page complete check screenshot
1   [2023-07-18 08:05:45] INFO: Take cumulative layout shift screenshot
1   [2023-07-18 08:05:46] INFO: No element attached to the entry in largest-contentful-paint
0   [2023-07-18 08:05:46] INFO: Take largest contentful paint screenshot
3   [2023-07-18 08:05:49] INFO: Get visual metrics from the video

Log extract from 28.2.0,
0   [2023-08-18 04:03:29] INFO: Navigating to url https://fly4.emirates.com iteration 1
141 [2023-08-18 04:05:50] INFO: Start to measure URP_Page_Load
30  [2023-08-18 04:06:20] INFO: Take after page complete check screenshot
1   [2023-08-18 04:06:21] INFO: Take cumulative layout shift screenshot
1   [2023-08-18 04:06:22] INFO: No element attached to the entry in largest-contentful-paint
0   [2023-08-18 04:06:22] INFO: Take largest contentful paint screenshot
3   [2023-08-18 04:06:25] INFO: Get visual metrics from the video

manjunathpremkumar commented 1 year ago

@soulgalore - need your help!

soulgalore commented 1 year ago

Hi @manjunathpremkumar in your script, what happens between navigate and Start to measure URP_Page_Load?

Looking in the changelog that is jump from Chrome 106 to 114. That's a big jump. At Wikimedia we handle that by updating to every major Chrome version, one step at time, that's the only way we can see when Chrome increase/decrease our metrics. Also with the auto update in Chrome our users are updating quite fast to the latest version, so to make sure we measure the performance as our users get it, we keep the browser versions updated as they are released.

manjunathpremkumar commented 1 year ago

Thanks for the inputs, between navigate to start to measure this is what the logs I see,

1 | [2023-08-18 04:06:33] INFO: Using CPUThrottlingRate: 1.5 -- | -- 0 | [2023-08-18 04:06:33] INFO: Navigating to url https://fly4.emirates.com iteration 2 0 | [2023-08-18 04:06:33] INFO: Use Chrome trace categories: -*,disabled-by-default-lighthouse,v8,v8.execute,blink.user_timing,devtools.timeline,disabled-by-default-devtools.timeline,disabled-by-default-devtools.timeline.stack 142 | [2023-08-18 04:08:55] INFO: Start to measure URP_Page_Load 29 | [2023-08-18 04:09:24] INFO: Take after page complete check screenshot 1 | [2023-08-18 04:09:25] INFO: Take cumulative layout shift screenshot 1 | [2023-08-18 04:09:26] INFO: No element attached to the entry in largest-contentful-paint 0 | [2023-08-18 04:09:26] INFO: Take largest contentful paint screenshot 3 | [2023-08-18 04:09:29] INFO: Get visual metrics from the video 0 | [2023-08-18 04:09:29] INFO: Use the visual metrics portable script 6 | [2023-08-18 04:09:35] INFO: VisualMetrics: FirstVisualChange: 2.93s SpeedIndex: 4.30s VisualComplete85: 6.47s LastVisualChange: 8.03s 0 | [2023-08-18 04:09:35] INFO: https://dummy.emirates.com/dummy/ TTFB: 1.08s DOMContentLoaded: 2.33s firstPaint: 1.26s FCP: 1.26s LCP: 1.64s Load: 4.12s TBT: 1.11s CLS:0.0202 1 | [2023-08-18 04:09:36] INFO: Using CPUThrottlingRate: 1.5 0 | [2023-08-18 04:09:36] INFO: Navigating to url https://fly4.emirates.com iteration 3

soulgalore commented 1 year ago

Ah I meant your script. Something like this:

navigate("your_url"); 
... <--- do you do something here in between?
measure.start('URP_Page_Load');

manjunathpremkumar commented 1 year ago

navigate("your_url"); user will enter the details for flight search, passengers clicks on go and then comes measure.start('URP_Page_Load');

checking with respective teams if something got introduced

manjunathpremkumar commented 1 year ago

@soulgalore - looks like search operation time has increased and nothing to do with measure.start. I can close this as dummy defect

sitespeedio / sitespeed.io