Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Using Server-Timing to Connect the Dots.pdf

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.

Colin Bendell

October 14, 2018
Tweet

More Decks by Colin Bendell

Other Decks in Programming

Transcript

  1. Today •Psychology of the User XP •Connecting User & Service

    Telemetry •Efficient Multi-Variant Analysis
  2. "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"
  3. ??

  4. Front End Server AuthGate Radius CMS DB: Prod lookup DB:

    inventory DB: Geo- Price DAM Storage User #!"#
  5. Front End Server AuthGate Radius CMS DB: Prod lookup DB:

    inventory DB: Geo- Price DAM Storage User #!"# User #$"%
  6. Front End Server AuthGate Radius CMS DB: Prod lookup DB:

    inventory DB: Geo- Price DAM Storage User ! ! ! ! ! ! ! ! !
  7. 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 !
  8. 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
  9. Headwinds & Considerations • Performance v. Product • Log ownership

    • COGS of Tracing • Hawthorn Effect • GDPR
  10. • Share identifiers • Compare both sides (Server:Server, User:Server) •

    Collect User telemetry (eg: boomerang, LUX, mPulse) • Server-Timing is more than timing
  11. Front End Server AuthGate Radius CMS DB: Prod lookup DB:

    inventory DB: Geo- Price DAM Storage! ! ! ! ! ! ! Option 1: Identifier Inheritance
  12. 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
  13. 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
  14. { 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
  15. Strategy 1: Shared Identifier • Connect logging • Option 1:

    Inherit a shared ID • Option 2: Collect late with Server-"Timing" API
  16. 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
  17. 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"
  18. Strategy 2 Annotate Essentials • clock-time vs effort-time • Normalize

    early; add useful information early • Eg: Primary Keys, Non-Critical Errors
  19. 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
  20. { 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
  21. Strategy 3 • The network is not zero • Use

    Server-Timing to measure time dilation • Compare server:server
  22. Front End Server AuthGate Radius CMS DB: Prod lookup DB:

    inventory DB: Geo- Price DAM Storage User
  23. { "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 } }
  24. { "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": [] }
  25. 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 }
  26. 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"
  27. 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
  28. Strategy 4 •Use BeaconAPI to send user experience logs back

    •NavTiming, UserTiming APIs •Server-Timing is accessible in JavaScript
  29. Front End Server AuthGate Radius CMS DB: Prod lookup DB:

    inventory DB: Geo- Price DAM Storage User ! ! ! ! ! ! ! ! ! !
  30. Import Log Ship Airflow Kinesis Normalize Spark Annotation Sanitization Store

    Snowflake (snowpipe) Rollups Analyze BI (Qliksense) R Jupyter
  31. Take Action • Share identifiers • Compare both sides (Server:Server,

    User:Server) • Collect User telemetry (eg: boomerang, LUX, mPulse) • Server-Timing is more than timing