fix: use performance.now() for server timing headers (#338)

Replace Date.now() with performance.now() for better timing info.

Also limit precision to ms for a smaller server-timing header.

Author: achingbrain

packages/verified-fetch/README.md

@@ -811,6 +811,11 @@ Detailed timing is found in the [Server-Timing](https://developer.mozilla.org/en
 HTTP header that is returned with every response when a resource is requested
 with the `withServerTiming` init option set to `true`.
 
+The `dur` field is in milliseconds, so `dur=100` took 100ms. It is possible
+to measure in greater precision, but given these are network operations it's
+better to limit the precision and have a smaller header size, since
+downloading the headers impacts the time to first byte.
+
 To prevent the header value growing too large, PeerIDs/CIDs are truncated to
 their first 10 characters and common strings are abbreviated.
 
@@ -833,7 +838,7 @@ follow.
 A full header might look like:
 
 ```
-i;dur=0.000,p;dur=0.000;desc="h,bagqbeaawn",p;dur=0.000;desc="h,bagqbeaawn",p;dur=1.000;desc="h,bagqbeaa7n",p;dur=1.000;desc="h,bagqbeaa7n",f;dur=1.000;desc="h,4",f;dur=1.000;desc="h,4",f;dur=144.000;desc="l,0",f;dur=144.000;desc="l,0",c;dur=206.000;desc="t,bagqbeaa7n,h",b;dur=1.000;desc="t,bagqbeaa7n,bafybeigoc"
+i;dur=0,p;dur=0;desc="h,bagqbeaawn",p;dur=0;desc="h,bagqbeaawn",p;dur=1;desc="h,bagqbeaa7n",p;dur=1;desc="h,bagqbeaa7n",f;dur=1;desc="h,4",f;dur=1;desc="h,4",f;dur=144;desc="l,0",f;dur=144;desc="l,0",c;dur=206;desc="t,bagqbeaa7n,h",b;dur=1;desc="t,bagqbeaa7n,bafybeigoc"
 ```
 
 Here resolving a CID to a CID+path took less than a millisecond (e.g. a bare

packages/verified-fetch/src/index.ts

@@ -779,6 +779,11 @@
  * HTTP header that is returned with every response when a resource is requested
  * with the `withServerTiming` init option set to `true`.
  *
+ * The `dur` field is in milliseconds, so `dur=100` took 100ms. It is possible
+ * to measure in greater precision, but given these are network operations it's
+ * better to limit the precision and have a smaller header size, since
+ * downloading the headers impacts the time to first byte.
+ *
  * To prevent the header value growing too large, PeerIDs/CIDs are truncated to
  * their first 10 characters and common strings are abbreviated.
  *
@@ -801,7 +806,7 @@
  * A full header might look like:
  *
  * ```
- * i;dur=0.000,p;dur=0.000;desc="h,bagqbeaawn",p;dur=0.000;desc="h,bagqbeaawn",p;dur=1.000;desc="h,bagqbeaa7n",p;dur=1.000;desc="h,bagqbeaa7n",f;dur=1.000;desc="h,4",f;dur=1.000;desc="h,4",f;dur=144.000;desc="l,0",f;dur=144.000;desc="l,0",c;dur=206.000;desc="t,bagqbeaa7n,h",b;dur=1.000;desc="t,bagqbeaa7n,bafybeigoc"
+ * i;dur=0,p;dur=0;desc="h,bagqbeaawn",p;dur=0;desc="h,bagqbeaawn",p;dur=1;desc="h,bagqbeaa7n",p;dur=1;desc="h,bagqbeaa7n",f;dur=1;desc="h,4",f;dur=1;desc="h,4",f;dur=144;desc="l,0",f;dur=144;desc="l,0",c;dur=206;desc="t,bagqbeaa7n,h",b;dur=1;desc="t,bagqbeaa7n,bafybeigoc"
  * ```
  *
  * Here resolving a CID to a CID+path took less than a millisecond (e.g. a bare

packages/verified-fetch/src/utils/server-timing.ts

@@ -1,10 +1,8 @@
 export class ServerTiming {
   private headers: string[]
-  private precision: number
 
   constructor () {
     this.headers = []
-    this.precision = 3
   }
 
   getHeader (): string {
@@ -18,13 +16,13 @@ export class ServerTiming {
       return await promise // Execute the function
     } finally {
       const endTime = performance.now()
-      const duration = (endTime - startTime).toFixed(this.precision) // Duration in milliseconds
+      const duration = endTime - startTime
 
       this.add(name, description, duration)
     }
   }
 
-  add (name: string, description: string, duration: number | string): void {
-    this.headers.push(`${name};dur=${Number(duration).toFixed(this.precision)}${description === '' ? '' : `;desc="${description}"`}`)
+  add (name: string, description: string, ms: number): void {
+    this.headers.push(`${name};dur=${Math.round(ms)}${description === '' ? '' : `;desc="${description}"`}`)
   }
 }

packages/verified-fetch/src/verified-fetch.ts

@@ -234,7 +234,7 @@ export class VerifiedFetch {
 
           if (evt.type === 'helia:routing:find-providers:start') {
             routingTimers[evt.detail.routing] = {
-              start: Date.now(),
+              start: performance.now(),
               found: 0
             }
           } else if (evt.type === 'helia:routing:find-providers:provider') {
@@ -244,18 +244,18 @@ export class VerifiedFetch {
 
             routingTimers[evt.detail.routing].found++
 
-            serverTiming.add(abbreviate('found-provider'), `${abbreviate(evt.detail.routing)},${truncate(evt.detail.provider.id)}`, Date.now() - routingTimers[evt.detail.routing].start)
+            serverTiming.add(abbreviate('found-provider'), `${abbreviate(evt.detail.routing)},${truncate(evt.detail.provider.id)}`, performance.now() - routingTimers[evt.detail.routing].start)
           } else if (evt.type === 'helia:routing:find-providers:end') {
             const routing = routingTimers[evt.detail.routing]
 
             if (routing == null) {
               return
             }
 
-            serverTiming.add(abbreviate('find-providers'), `${abbreviate(evt.detail.routing)},${routing.found}`, Date.now() - routing.start)
+            serverTiming.add(abbreviate('find-providers'), `${abbreviate(evt.detail.routing)},${routing.found}`, performance.now() - routing.start)
           } else if (evt.type === 'helia:block-broker:connect') {
             connectTimers[`connect-${evt.detail.broker}-${evt.detail.provider}`] = {
-              start: Date.now(),
+              start: performance.now(),
               transport: ''
             }
           } else if (evt.type === 'helia:block-broker:connected') {
@@ -265,17 +265,17 @@ export class VerifiedFetch {
               return
             }
 
-            serverTiming.add(abbreviate('connect'), `${abbreviate(evt.detail.broker)},${truncate(evt.detail.provider)},${abbreviateAddress(evt.detail.address)}`, Date.now() - start.start)
+            serverTiming.add(abbreviate('connect'), `${abbreviate(evt.detail.broker)},${truncate(evt.detail.provider)},${abbreviateAddress(evt.detail.address)}`, performance.now() - start.start)
           } else if (evt.type === 'helia:block-broker:request-block') {
-            blockTimers[`block-${evt.detail.broker}-${evt.detail.cid}-${evt.detail.provider}`] = Date.now()
+            blockTimers[`block-${evt.detail.broker}-${evt.detail.cid}-${evt.detail.provider}`] = performance.now()
           } else if (evt.type === 'helia:block-broker:receive-block') {
             const start = blockTimers[`block-${evt.detail.broker}-${evt.detail.cid}-${evt.detail.provider}`]
 
             if (start == null) {
               return
             }
 
-            serverTiming.add(abbreviate('block'), `${abbreviate(evt.detail.broker)},${truncate(evt.detail.provider)},${truncate(evt.detail.cid)}`, Date.now() - start)
+            serverTiming.add(abbreviate('block'), `${abbreviate(evt.detail.broker)},${truncate(evt.detail.provider)},${truncate(evt.detail.cid)}`, performance.now() - start)
           }
         }
       }