search

janodvarko / harviewer

HAR Viewer is a web application that allows visualizing HTTP Archive logs (HARs)
http://www.softwareishard.com/blog/har-viewer/
1.04k stars 184 forks source link

transaction (HarEntry) is shown with misleading start time and duration #123

Open ChrisLMerrill opened 6 years ago

ChrisLMerrill commented 6 years ago

I have a HAR file produced with Chrome. As the title says, it looks like one transaction is shown incorrectly. All the numbers are correct, but the bar placement/sizing is incorrect (relative to the bars for other transactions on the page). The other transactions on the page all finish within about 1.5 seconds (onLoad is ~750ms). The transaction that appears to be incorrect starts 12 seconds after the page start and lasts ~200ms. But on the chart, it is shown starting at page-start and the bar for the transaction spans the entire chart. The transaction duration is ~1/4 of the transaction above it, but is shown as a bar twice as long. The transaction is a post that leads to the next page. Is this a know problem in this situation? Or am I not reading the chart correctly?

screenshot

This is the page section of the HAR: 

      {
        "startedDateTime": "2018-08-09T14:06:24.487Z",
        "id": "page_3",
        "title": "http://demo6.webperformance.com/wp-login.php",
        "pageTimings": {
          "onContentLoad": 835.5770000002849,
          "onLoad": 853.505000000041
        }

And this is the entry:

      {
        "startedDateTime": "2018-08-09T14:06:36.487Z",
        "time": 207.55139399998708,
        "request": {
          "method": "POST",
          "url": "http://demo6.webperformance.com/wp-admin/post.php",
          "httpVersion": "HTTP/1.1",
          "headers": [
            {
              "name": "Cookie",
              "value": "wordpress_d9d908fe9735d102f9ca89afd2999055=demo%7C1533996065%7Ca16d7fe7ff46897f39c7cc434ce0ec26; wordpress_test_cookie=WP+Cookie+check; wordpress_logged_in_d9d908fe9735d102f9ca89afd2999055=demo%7C1533996065%7C5da2e094c128a947907c60b3ff76fdb6; wp-settings-time-3=1533823265"
            },
            {
              "name": "Origin",
              "value": "http://demo6.webperformance.com"
            },
            {
              "name": "Accept-Encoding",
              "value": "gzip, deflate"
            },
            {
              "name": "Host",
              "value": "demo6.webperformance.com"
            },
            {
              "name": "Accept-Language",
              "value": "en-US,en;q=0.9"
            },
            {
              "name": "User-Agent",
              "value": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.84 Safari/537.36"
            },
            {
              "name": "Content-Type",
              "value": "application/x-www-form-urlencoded; charset=UTF-8"
            },
            {
              "name": "Accept",
              "value": "*/*"
            },
            {
              "name": "Referer",
              "value": "http://demo6.webperformance.com/wp-admin/"
            },
            {
              "name": "X-Requested-With",
              "value": "XMLHttpRequest"
            },
            {
              "name": "Connection",
              "value": "keep-alive"
            },
            {
              "name": "Content-Length",
              "value": "155"
            }
          ],
          "queryString": [],
          "cookies": [
            {
              "name": "wordpress_d9d908fe9735d102f9ca89afd2999055",
              "value": "demo%7C1533996065%7Ca16d7fe7ff46897f39c7cc434ce0ec26",
              "expires": null,
              "httpOnly": false,
              "secure": false
            },
            {
              "name": "wordpress_test_cookie",
              "value": "WP+Cookie+check",
              "expires": null,
              "httpOnly": false,
              "secure": false
            },
            {
              "name": "wordpress_logged_in_d9d908fe9735d102f9ca89afd2999055",
              "value": "demo%7C1533996065%7C5da2e094c128a947907c60b3ff76fdb6",
              "expires": null,
              "httpOnly": false,
              "secure": false
            },
            {
              "name": "wp-settings-time-3",
              "value": "1533823265",
              "expires": null,
              "httpOnly": false,
              "secure": false
            }
          ],
          "headersSize": 790,
          "bodySize": 0,
          "postData": {
            "mimeType": "application/x-www-form-urlencoded; charset=UTF-8",
            "text": "post_title=title+of+post&content=content+of+post&action=post-quickdraft-save&post_ID=559&post_type=post&_wpnonce=006ef02e70&_wp_http_referer=%2Fwp-admin%2F",
            "params": [
              {
                "name": "post_title",
                "value": "title+of+post"
              },
              {
                "name": "content",
                "value": "content+of+post"
              },
              {
                "name": "action",
                "value": "post-quickdraft-save"
              },
              {
                "name": "post_ID",
                "value": "559"
              },
              {
                "name": "post_type",
                "value": "post"
              },
              {
                "name": "_wpnonce",
                "value": "006ef02e70"
              },
              {
                "name": "_wp_http_referer",
                "value": "%2Fwp-admin%2F"
              }
            ]
          }
        },
        "response": {
          "status": 200,
          "statusText": "OK",
          "httpVersion": "HTTP/1.1",
          "headers": [
            {
              "name": "Pragma",
              "value": "no-cache"
            },
            {
              "name": "Date",
              "value": "Thu, 09 Aug 2018 14:01:17 GMT"
            },
            {
              "name": "Vary",
              "value": "Accept-Encoding"
            },
            {
              "name": "Server",
              "value": "Apache"
            },
            {
              "name": "X-Powered-By",
              "value": "PHP/5.4.23"
            },
            {
              "name": "X-Frame-Options",
              "value": "SAMEORIGIN"
            },
            {
              "name": "Content-Type",
              "value": "text/html"
            },
            {
              "name": "Cache-Control",
              "value": "no-cache, must-revalidate, max-age=0"
            },
            {
              "name": "Transfer-Encoding",
              "value": "chunked"
            },
            {
              "name": "Connection",
              "value": "Keep-Alive"
            },
            {
              "name": "Keep-Alive",
              "value": "timeout=2, max=100"
            },
            {
              "name": "Expires",
              "value": "Wed, 11 Jan 1984 05:00:00 GMT"
            }
          ],
          "cookies": [],
          "content": {
            "size": 1508,
            "mimeType": "text/html",
            "compression": -12
          },
          "redirectURL": "",
          "headersSize": 370,
          "bodySize": 1520,
          "_transferSize": 1890
        },
        "cache": {},
        "timings": {
          "blocked": 0.3763940000001421,
          "dns": 0.008000000000000007,
          "ssl": -1,
          "connect": 15.181000000000001,
          "send": 0.17999999999999972,
          "wait": 190.5530000000809,
          "receive": 1.2529999999060237,
          "_blocked_queueing": 0.394000000142114
        },
        "serverIPAddress": "54.197.179.87",
        "connection": "7243",
        "pageref": "page_3"
      },
gitgrimbo commented 6 years ago

Hi, I think this is deliberate. I think that if there is a long enough time gap between requests then HAR Viewer will draw a slightly thicker line between requests and draw the new request at the left-hand margin (see the arrows below, pointing to the thicker line and the new request at the left-hand margin).

This behaviour is to avoid the timeline getting 'too wide', or the request bars getting 'too small' relative to the total elapsed time.

I'll need to double-check the code, but I think that's what's happening.

image

UPDATE - I think HAR Viewer calls these breaks in the request list 'phases' - see https://github.com/janodvarko/harviewer/blob/4dfe1e9109014f637d23fb99cf3c0652db44f30a/webapp/scripts/preview/requestList.js#L789

There is a cookie value called phaseInterval that can be set to a value in milliseconds. This defaults to 4000ms. So if two requests are separated by 4 seconds, by default they will be broken into two separate 'phases'. You should be able to manually set this cookie and see the effects.

So because your post.php request starts at 2018-08-09T14:06:36.487Z and the favicon.ico request started maybe a couple of seconds after page start (at 2018-08-09T14:06:24.487Z), this is >= 4 seconds, and so will trigger a new phase.

UPDATE 2 - The splitting of requests into phases will only happen to requests that are started after the onLoad time.