{"action":"created","issue":{"url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/539","labels_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/539/labels{/name}","comments_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/539/comments","events_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/539/events","html_url":"https://github.com/WPO-Foundation/webpagetest/issues/539","id":120185618,"number":539,"title":"Overwritten user timing marks get wrongly exported ","user":{"login":"laurentgoudet","id":2169585,"avatar_url":"https://avatars.githubusercontent.com/u/2169585?v=3","gravatar_id":"","url":"https://api.github.com/users/laurentgoudet","html_url":"https://github.com/laurentgoudet","followers_url":"https://api.github.com/users/laurentgoudet/followers","following_url":"https://api.github.com/users/laurentgoudet/following{/other_user}","gists_url":"https://api.github.com/users/laurentgoudet/gists{/gist_id}","starred_url":"https://api.github.com/users/laurentgoudet/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/laurentgoudet/subscriptions","organizations_url":"https://api.github.com/users/laurentgoudet/orgs","repos_url":"https://api.github.com/users/laurentgoudet/repos","events_url":"https://api.github.com/users/laurentgoudet/events{/privacy}","received_events_url":"https://api.github.com/users/laurentgoudet/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2015-12-03T14:40:02Z","updated_at":"2015-12-03T15:28:53Z","closed_at":null,"body":"I'm using @stevesouders Hero Images Custom Metrics technique (http://www.stevesouders.com/blog/2015/05/12/hero-image-custom-metrics), with the difference that I do a `clearMarks`/`mark` in the load event handler to have a single timing mark for the metric I'm interested in. That works great in the DevTool (try `performance.getEntriesByName('profile_image')[0].startTime` or  `performance.getEntriesByName('profile_image')[0].startTime` on https://www.freelancer.com/u/best1.html).\r\n\r\nHowever, while looking into why the SpeedCurve graphs were fluctuating that much, I found out that WPT was not reporting these marks correctly and they were not reflecting the reality. When looking at http://www.webpagetest.org/video/compare.php?tests=151203_VH_fab308d054f763310634beef3390b8b9-r:1-c:1, it seems that WPT captures the first call to `mark` for a specific mark name and doesn't take in account the subsequent `clearMark` + `mark` (in the load handler if the image wasn't yet loaded).\r\n\r\nGlancing at the code the `USER_TIMING_SCRIPT` script defines in `agent/browser/chrome/extension/release/wpt/background.js` seems perfectly fine, however if my (non existent) c++ skills are right that `collectstats` function is called every 100ms, and the HAR export confirms this (multiple instances of the same time mark with different values).\r\n\r\nTL;DR: can the user timing marks behave like in the DevTools, i.e. only export the last values?"},"comment":{"url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/comments/161676117","html_url":"https://github.com/WPO-Foundation/webpagetest/issues/539#issuecomment-161676117","issue_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/539","id":161676117,"user":{"login":"laurentgoudet","id":2169585,"avatar_url":"https://avatars.githubusercontent.com/u/2169585?v=3","gravatar_id":"","url":"https://api.github.com/users/laurentgoudet","html_url":"https://github.com/laurentgoudet","followers_url":"https://api.github.com/users/laurentgoudet/followers","following_url":"https://api.github.com/users/laurentgoudet/following{/other_user}","gists_url":"https://api.github.com/users/laurentgoudet/gists{/gist_id}","starred_url":"https://api.github.com/users/laurentgoudet/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/laurentgoudet/subscriptions","organizations_url":"https://api.github.com/users/laurentgoudet/orgs","repos_url":"https://api.github.com/users/laurentgoudet/repos","events_url":"https://api.github.com/users/laurentgoudet/events{/privacy}","received_events_url":"https://api.github.com/users/laurentgoudet/received_events","type":"User","site_admin":false},"created_at":"2015-12-03T15:28:53Z","updated_at":"2015-12-03T15:28:53Z","body":"> Do you have code attached to multiple profile_image's or just the one?\r\n\r\nJust the one\r\n\r\n> Looking at the script after the image it looks like it sets the mark as soon as the script is run (before the image loads) and then again in the onload handler for the profile image.\r\n\r\nAs mentioned by Steve \"Therefore, to create a custom metric that determines when an image is displayed you should take the max of the values reported by the inline script timer and image onload.\", it seems to be the most accurate way to know when an image is displayed (http://stevesouders.com/tests/image-custom-metric.php), and I've confirmed that with multiple runs in the DevTools with the filmstrip view (with a primed cache or not).\r\n\r\nHowever, I do agree that looking at the WPT results that technique doesn't seem to work :(. The HAR export of http://www.webpagetest.org/video/compare.php?tests=151203_VH_fab308d054f763310634beef3390b8b9-r:1-c:0 still contains 2 different sets of values but none of those seem to correlate to the actual user experience:\r\n\r\nReal (from the filmstrip): 3.2s, 4.6s\r\nReported (in the waterfall): 2.8, 4.2s\r\n\r\nFirst set:\r\n```json\r\n\"_date\":1448888456,\r\n\"_userTime.profile_image\":2839,\r\n\"_userTime.cover_image\":5581,\r\n```\r\n\r\nSecond set:\r\n```json\r\n\"_date\":1448888495,\r\n\"_userTime.profile_image\":2293,\r\n\"_userTime.cover_image\":4400,\r\n```\r\n\r\n"}}