Using Server-Timing to Connect the Dots.pdf

Attributing causation is difficult. How did this micro service impact user experience? Are we sure that this user behaviour was caused by this code change? The distribution of user experience behaviour is always very wide with many variables. This is a challenge when trying to link causation. In this talk we will explore 5 strategies that how Cloudinary is using to closing the causation loop – from application telemetry to end user experience.

Transcript

1. To Connect the Dogs @ColinBendell CTO Office, Cloudinary Server-Timing Dots DATA
2. @ColinBendell
5. Today •Psychology of the User XP •Connecting User & Service Telemetry •Efficient Multi-Variant Analysis
6. How To: •impress your Boss •impress your Co-Workers •impress your Mom Put Another Way…
9. The User Experience
11. "I just want to share my photos from last night" "I want to buy a birthday present for mom" "I want to check the news"
12. Sometimes experience doesn't match expectations
13. #WebPerf: Correlating Performance and Conversion
16. ??
17. “We develop in the Zoo, But release in the Jungle” -Melanie Cey
18. What Happened? •Blue-green / MV test? •Service disruption? •Data Inconsistency? •Poor UX? •MiTM?
19. Our EcoSystem of the Telemetry Data
21. 88.225.187.184 GET /cornfield.gif 200 20482 41110 $ cat access.log|grep cornfield.gif ¯\_(
    )_/¯
22. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage User #!"#
23. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage User #!"# User #$"%
24. 88.225.187.184 GET /cornfield.gif 200 20482 41110 $ cat access.log|grep cornfield.gif ¯\_(
    )_/¯
25. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage User ! ! ! ! ! ! ! ! !
26. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage User !
27. Oct 13 17:52:20 syslogd[49]: ASL Sender Statistics Oct 13 17:52:20 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 17:52:20 --- last message repeated 1 time --- Oct 13 17:52:20 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70139): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/Frameworks/IDEKit.fra Oct 13 17:52:20 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70139): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/SharedFrameworks/LLDB Oct 13 17:52:59 idea[70147]: allVms required 1.8*,1.8+ Oct 13 17:52:59 idea[70147]: Value of IDEA_VM_OPTIONS is (null) Oct 13 17:52:59 idea[70147]: Processing VMOptions file at /Users/colin/Library/Application Support/JetBrains/Toolbox/apps/IDEA-U/ch-0/182.4505.22/IntelliJ IDEA.app.vmoptions Oct 13 17:52:59 idea[70147]: Done Oct 13 17:53:01 idea[70147]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 17:53:02 com.apple.xpc.launchd[1] (com.apple.quicklook[70271]): Endpoint has been activated through legacy launch(3) APIs. Please switch to XPC or bootstrap_check_in(): com.apple.quicklook Oct 13 17:53:10 xpcproxy[70325]: libcoreservices: _dirhelper_userdir: 529: bootstrap_look_up returned (ipc/send) invalid destination port Oct 13 17:56:42 com.apple.xpc.launchd[1] (com.apple.appkit.xpc.openAndSavePanelService[69418]): Service did not exit 5 seconds after SIGTERM. Sending SIGKILL. Oct 13 18:00:33 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.user.501): Service "com.apple.xpc.launchd.unmanaged.loginwindow.109" tried to register for endpoint "com.apple.tsm.uiserver" already registered by Oct 13 18:27:56 --- last message repeated 1 time --- Oct 13 18:27:56 syslogd[49]: ASL Sender Statistics Oct 13 18:28:01 iTunesCacheExtension[70380]: objc[70380]: Class ITNSImage is implemented in both /System/Library/Frameworks/iTunesLibrary.framework/Versions/A/iTunesLibrary (0x7fff876d7568) and /Applications/iTunes.app Oct 13 18:28:01 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:28:02 --- last message repeated 1 time --- Oct 13 18:28:02 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70379): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/Frameworks/IDEKit.fra Oct 13 18:28:02 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70379): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/SharedFrameworks/LLDB Oct 13 18:30:24 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.user.501): Service "com.apple.xpc.launchd.unmanaged.loginwindow.109" tried to register for endpoint "com.apple.tsm.uiserver" already registered by Oct 13 18:31:44 --- last message repeated 1 time --- Oct 13 18:32:04 com.apple.xpc.launchd[1] (com.apple.eospreflightagent): Service only ran for 521 seconds. Pushing respawn out by 379 seconds. Oct 13 18:32:04 xpcproxy[70406]: libcoreservices: _dirhelper_userdir: 529: bootstrap_look_up returned (ipc/send) invalid destination port Oct 13 18:32:12 xpcproxy[70420]: libcoreservices: _dirhelper_userdir: 529: bootstrap_look_up returned (ipc/send) invalid destination port Oct 13 18:32:13 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:32:38 System Preferences[70426]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 18:32:38 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:32:49 com.apple.preferences.sharing.remoteservice[70435]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 18:32:54 com.apple.xpc.launchd[1] (com.apple.WebKit.Networking.E25DA39A-B766-4939-9E11-5B36F36493A7[70409]): Service exited with abnormal code: 1 Oct 13 18:33:02 xpcproxy[70439]: libcoreservices: _dirhelper_userdir: 529: bootstrap_look_up returned (ipc/send) invalid destination port Oct 13 18:34:46 ContainerMetadataExtractor[70445]: objc[70445]: Class BRMangledID is implemented in both /System/Library/PrivateFrameworks/CloudDocs.framework/Versions/A/CloudDocs (0x7fff88192dd8) and /System/Library/P Oct 13 18:35:10 com.apple.xpc.launchd[1] (com.apple.quicklook[70448]): Endpoint has been activated through legacy launch(3) APIs. Please switch to XPC or bootstrap_check_in(): com.apple.quicklook Oct 13 18:35:15 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:35:15 Notes[70463]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 18:38:03 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:38:04 syslogd[49]: ASL Sender Statistics Oct 13 18:38:03 iTunesCacheExtension[70472]: objc[70472]: Class ITNSImage is implemented in both /System/Library/Frameworks/iTunesLibrary.framework/Versions/A/iTunesLibrary (0x7fff876d7568) and /Applications/iTunes.app Oct 13 18:38:03 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:38:04 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70468): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/Frameworks/IDEKit.fra Oct 13 18:38:04 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70468): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/SharedFrameworks/LLDB Oct 13 18:42:23 CharacterPalette[70475]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 18:42:26 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:44:07 CharacterPalette[70478]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 18:44:33 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:45:16 OSDUIHelper[70480]: DEPRECATED USE in libdispatch client: dispatch source activated with no event handler set; set a breakpoint on _dispatch_bug_deprecated to debug Oct 13 18:47:51 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.user.501): Service "com.apple.xpc.launchd.unmanaged.loginwindow.109" tried to register for endpoint "com.apple.tsm.uiserver" already registered by Oct 13 18:48:04 --- last message repeated 1 time --- Oct 13 18:48:04 syslogd[49]: ASL Sender Statistics Oct 13 18:48:05 iTunesCacheExtension[70485]: objc[70485]: Class ITNSImage is implemented in both /System/Library/Frameworks/iTunesLibrary.framework/Versions/A/iTunesLibrary (0x7fff876d7568) and /Applications/iTunes.app Oct 13 18:48:05 com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): Unknown key for integer: _DirtyJetsamMemoryLimit Oct 13 18:48:05 --- last message repeated 1 time --- Oct 13 18:48:05 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70487): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/Frameworks/IDEKit.fra Oct 13 18:48:05 com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.pid.IDECacheDeleteAppExtension.70487): Path not allowed in target domain: type = pid, path = /Applications/Xcode.app/Contents/SharedFrameworks/LLDB Oct 13 19:00:38 syslogd[49]: ASL Sender Statistics
28. So you've got a data lake…
29. Headwinds & Considerations • Performance v. Product • Log ownership • COGS of Tracing • Hawthorn Effect • GDPR
30. • Share identifiers • Compare both sides (Server:Server, User:Server) • Collect User telemetry (eg: boomerang, LUX, mPulse) • Server-Timing is more than timing
31. Strategy 1 Annotate your logging with a shared identifier
32. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage! ! ! ! ! ! ! Option 1: Identifier Inheritance
33. 88.225.187.184 GET /corn.gif 200 20482 41110 ID_1234.56 $ cat access.log|grep corn.gif $ cat db-access.log|grep ID1234.56 ID_1234.56 "SELECT URL FROM FUNNY_GIFS …" 2043
34. Option 2: Late Annotation with Server-Timing
35. Server-Timing: cloudinary, dur="10", desc="Bicycle Cat" name description duration
36. GET /api/db/product HTTP/1.1 Host: example.com HTTP/1.1 200 OK Server-Timing: id, desc="sub-def456.78" Server-Timing: db, dur=2043 Request Response
37. { ip: "88.225.187.184", url: "/corn.gif", status: 200, size:" 20482", duration: 41110, id: "ID_1234.56", db: [{ id: "sub-def456.78", dur: 2043 }] } $ cat access.log|grep corn.gif
38. Strategy 1: Shared Identifier • Connect logging • Option 1: Inherit a shared ID • Option 2: Collect late with Server-"Timing" API
39. Strategy 2 Use Server-"Timing" to pass essential details upstream
40. GET /cms/sale.html HTTP/1.1 Host: example.com HTTP/1.1 200 OK Server-Timing: db-id, desc="sub-def456.78" Server-Timing: db, dur=2043 Request Response Server-Timing: cms-id, desc="abc123.45" Server-Timing: cms, dur=41110 Stash & Remove Add & Annotate
41. GET /cms/sale.html HTTP/1.1 Host: example.com HTTP/1.1 200 OK Server-Timing: db-reqid, desc="sub-def456.78" Server-Timing: db, dur=2043 Request Response Server-Timing: cms-reqid, desc="abc123.45" Server-Timing: cms, dur=41110 Server-Timing: error, desc="personalisation timeout" Server-Timing: key, desc="shoes123, shirts456"
42. 44 Server-Timing is more than Timing
43. Strategy 2 Annotate Essentials • clock-time vs effort-time • Normalize early; add useful information early • Eg: Primary Keys, Non-Critical Errors
44. Strategy 3 Compare both sides
46. Front End Server DB: Prod lookup Front End Server AuthGate CMS DAM Radius Storage DB: Geo-Price DB: inventory DB: Prod lookup Each Service Has a Hidden Cost: Infrastructure
47. Front End Server DB: Prod lookup 41,115ms 41,110ms 22,083 ms 2043 ms
48. { ip: "88.225.187.184", url: "/corn.gif", status: 200, size:" 20482", duration: 41110, id: "ID_1234.56", db: [{ id: "sub-def456.78", dur: 2043, total: 22033, }] } $ cat access.log|grep corn.gif
49. Strategy 3 • The network is not zero • Use Server-Timing to measure time dilation • Compare server:server
50. Strategy 4 End User Telemetry
51. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage User
52. https://www.w3.org/wiki/Web_Performance/Publications
54. function logData() { navigator.sendBeacon("/log", data); }
56. Navigation Timing API
57. window.performance
58. { "timeOrigin": 1528900579651.6672, "timing": { "navigationStart": 1528900579651, "unloadEventStart": 0, "unloadEventEnd": 0, "redirectStart": 0, "redirectEnd": 0, "fetchStart": 1528900583010, "domainLookupStart": 1528900579730, "domainLookupEnd": 1528900579730, "connectStart": 1528900579730, "connectEnd": 1528900579761, "secureConnectionStart": 1528900579733, "requestStart": 1528900579761, "responseStart": 1528900582922, "responseEnd": 1528900583010, "domLoading": 1528900583014, "domInteractive": 1528900583849, "domContentLoadedEventStart": 1528900583849, "domContentLoadedEventEnd": 1528900583876, "domComplete": 1528900585616, "loadEventStart": 1528900585617, "loadEventEnd": 1528900585856 }, "navigation": {"type": 0, "redirectCount": 0 } }
61. window.performance.getEntries()[0]
62. { "name": "https://ajax.googleapis.com/ajax/libs/jquery/1.11.2/jquery.min.js", "entryType": "resource", "startTime": 928.70000000039, "duration": 425.8000000008906, "initiatorType": "script", "nextHopProtocol": "h2", "workerStart": 0, "redirectStart": 0, "redirectEnd": 0, "fetchStart": 928.70000000039, "domainLookupStart": 937.4000000025262, "domainLookupEnd": 945.9000000024389, "connectStart": 945.9000000024389, "connectEnd": 967.5999999999476, "secureConnectionStart": 946.2000000021362, "requestStart": 949.5999999999185, "responseStart": 970.9000000002561, "responseEnd": 1354.5000000012806, "transferSize": 33798, "encodedBodySize": 33495, "decodedBodySize": 95931, "serverTiming": [] }
63. let url = “https://bendell.ca/logo.png”; let me = performance.getEntriesByName(url)[0]; let timings = { loadTime: me.duration, dns: me.domainLookupEnd - me.domainLookupStart, tcp: me.connectEnd - me.connectStart, waiting: me.responseStart - me.requestStart, fetch: me.responseEnd - me.responseStart }
65. GET /resource HTTP/1.1 Host: example.com HTTP/1.1 200 OK Server-Timing: cdn, dur=130, desc="MISS" Server-Timing: cloudinary, dur="10", desc="thumbnail"
66. { let url = 'https://example.com/resource.jpg’; let severEntries[] = window.performance.getEntriesByName(url) .filter((name) => name === "server"); }
67. GET /resource HTTP/1.1 Host: example.com HTTP/1.1 200 OK Server-Timing: cdn, dur=130, desc="MISS" Server-Timing: cloudinary, dur="10", desc="thumbnail" Server-Timing: is-cellular, desc="true" Server-Timing: rtt, dur=150
68. Strategy 4 •Use BeaconAPI to send user experience logs back •NavTiming, UserTiming APIs •Server-Timing is accessible in JavaScript
69. Strategy 5 Parse & Simplify
70. Front End Server AuthGate Radius CMS DB: Prod lookup DB: inventory DB: Geo- Price DAM Storage User ! ! ! ! ! ! ! ! ! !
71. Import Log Ship Airflow Kinesis Normalize Spark Annotation Sanitization Store Snowflake (snowpipe) Rollups Analyze BI (Qliksense) R Jupyter
72. Take Action • Share identifiers • Compare both sides (Server:Server, User:Server) • Collect User telemetry (eg: boomerang, LUX, mPulse) • Server-Timing is more than timing
73. Thank-You!
74. @ColinBendell