Skip to content

Conversation

@edge33
Copy link
Contributor

@edge33 edge33 commented Aug 4, 2025

✨ Feature: Support RFC 3339 Timestamps with Nanosecond Precision

This update introduces support for RFC 3339-formatted timestamps with nanosecond precision, enabling higher-resolution time tracking for logs—especially useful in distributed systems, observability pipelines, and time-sensitive applications.

🔍 Background

Pino’s default timestamp format is optimized for performance and compactness, typically using Date.now() or epochTime in milliseconds. However, modern observability stacks and structured logging systems (e.g., OpenTelemetry, Loki, or JSON-based pipelines) often require nanosecond precision and ISO 8601-compliant timestamp formats.

The need for increased timestamp precision arose from observing that log entries occasionally appeared out of order in Google Cloud Logging. This was due to multiple entries sharing the same millisecond timestamp, resulting in collisions. By adopting nanosecond-level precision, we significantly reduce the likelihood of these collisions and preserve the correct log order. The performance overhead of formatting timestamps with nanosecond precision is negligible.

✅ What’s New

New timestamp function: pino.timestamp.isoTimeNanos

Outputs timestamps in RFC 3339 format with nanosecond precision, e.g.:

2025-08-02T14:36:12.123456789Z

Built using process.hrtime.bigint() to ensure monotonic and high-resolution timing

Compatible with pino.transport() and all core Pino features

🔧 Usage

const pino = require('pino')

const logger = pino({
  timestamp: pino.timestamp.isoTimeNanos
})

logger.info('High-resolution log timestamp')

📈 Use Cases
Distributed tracing and telemetry

Scientific or financial applications requiring precise time tracking

Compatibility with logging systems expecting strict RFC 3339 formats

⚠️ Notes
Nanosecond precision is only available in Node.js versions that support process.hrtime.bigint().

Minor overhead may be introduced due to the additional precision formatting.

🧪 Testing
Thorough tests have been added to validate:

Correct formatting of timestamps

Monotonic behavior

🚀 Performance

Benchmarking was done using the following script:

// Default pino ISO timestamp (RFC 3339 with millisecond precision)
const defaultTimestamp = () => `,"time":"${new Date(Date.now()).toISOString()}"` // using Date.now() for testability
const startHRTimeNs = process.hrtime.bigint()
const startWallTimeNs = BigInt(Date.now()) * 1_000_000n

const MS_MULTIPLIER = 1000
const NS_DIVISOR = 1_000_000_000n

// Custom RFC 3339 with fake nanosecond precision
function customNanosecondTimestamp () {
  const totalNs = startWallTimeNs + (process.hrtime.bigint() - startHRTimeNs)
  const iso = new Date(
    Number(totalNs / NS_DIVISOR) * MS_MULTIPLIER
  ).toISOString()

  return `,"time":"${iso.slice(0, 19)}.${(totalNs % NS_DIVISOR)
    .toString()
    .padStart(9, '0')}Z"`
}

// Benchmarking utility
function benchmark (fn, label, iterations = 100000) {
  const start = process.hrtime.bigint()
  for (let i = 0; i < iterations; i++) {
    fn()
  }
  const end = process.hrtime.bigint()
  const durationMs = Number(end - start) / 1e6
  console.log(`${label}: ${durationMs.toFixed(2)} ms for ${iterations} runs`)
}

// Run benchmarks
const iterations = 1_000_000
console.log(`Benchmarking ${iterations} iterations...`)
benchmark(defaultTimestamp, 'Default Pino timestamp', iterations)
benchmark(customNanosecondTimestamp, 'Custom nanosecond timestamp', iterations)

outcome:

Benchmarking 1000000 iterations...
Default Pino timestamp: 420.57 ms for 1000000 runs
Custom nanosecond timestamp: 465.04 ms for 1000000 runs

Copy link
Contributor

@simoneb simoneb left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, nice addition 🚀

Copy link
Member

@mcollina mcollina left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also docs are missing

Date.now = () => ms

const hrTimeBigint = process.hrtime.bigint
process.hrtime.bigint = () => 101794177055958n
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you avoid this top level changes? This would make the test unmaintanable.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

they're run in isolation though, aren't they?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, but this file is structured to contain multiple tests anyway (via test) and if you look there is also some duplicated logic inside.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I moved the mocking logic inside the test, the logic duplication is driven by the need of returning two different values in order to compute the timestamp, it simulates time passing. Also, the fact that I need to store the value of process.hrtime.bigint() when the app starts, requires the mocked function to be created before the module is required, hence the need of importing the module inside the test function. I'm open to different approach if you have ideas here

pino.d.ts Outdated
/*
* Returns RFC 3339-formatted time in UTC
*/
isoTimeNanos: TimeFn;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please update the types tests too

@edge33 edge33 requested a review from mcollina August 6, 2025 12:10
Co-authored-by: Andrea Carraro <[email protected]>
Copy link
Member

@mcollina mcollina left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

Copy link
Member

@jsumners jsumners left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The precision is "nanosecond." Also, please review linting and testing errors.

const { test } = require('tap')
const { sink, once } = require('./helper')

test('pino.stdTimeFunctions.isoTimeNanos returns RFC 3339 timestamps', async ({ equal }) => {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Dropping here a debatable idea to make this test a bit more explicit.

test('pino.stdTimeFunctions.isoTimeNanos returns RFC 3339 timestamps', async ({ equal }) => {
  // Mock Date.now at module initialization time
  const now = Date.now
  Date.now = () => new Date('2025-08-01T15:03:45.000000000Z').getTime()

  // Mock process.hrtime.bigint at module initialization time
  const hrTimeBigint = process.hrtime.bigint
  process.hrtime.bigint = () => 100000000000000n

  const pino = require('../')

  const opts = {
    timestamp: pino.stdTimeFunctions.isoTimeNanos
  }
  const stream = sink()

  // Mock process.hrtime.bigint at invocation time
  process.hrtime.bigint = () => 100000000000000n + 12345678n

  const instance = pino(opts, stream)
  instance.info('foobar')
  const result = await once(stream, 'data')

  equal(result.hasOwnProperty('time'), true)
  equal(result.time, '2025-08-01T15:03:45.012345678Z')

  Date.now = now
  process.hrtime.bigint = hrTimeBigint
})

@edge33 edge33 force-pushed the feat/timestamp-rfc3339-nanos branch from 1022d5f to 4b019e7 Compare August 9, 2025 13:08
@edge33 edge33 requested a review from jsumners August 9, 2025 13:08
@edge33
Copy link
Contributor Author

edge33 commented Aug 9, 2025

refactored the function to squeeze more performance out of it, latest benchmark run:

Benchmarking 1000000 iterations...
Default Pino timestamp: 447.21 ms for 1000000 runs
Custom nanosecond timestamp: 232.79 ms for 1000000 runs

@edge33 edge33 requested a review from jsumners August 12, 2025 12:07
@edge33
Copy link
Contributor Author

edge33 commented Sep 11, 2025

@jsumners sorry for the ping 🙏 , but this PR has been pending for a month now, can I get a new review when you have the chance? :)

@jsumners jsumners merged commit feef9ac into pinojs:main Sep 18, 2025
@edge33 edge33 deleted the feat/timestamp-rfc3339-nanos branch October 18, 2025 10:04
alanplatt added a commit to DEFRA/grants-ui that referenced this pull request Nov 7, 2025
![snyk-top-banner](https://res.cloudinary.com/snyk/image/upload/r-d/scm-platform/snyk-pull-requests/pr-banner-default.svg)


<h3>Snyk has created this PR to upgrade pino from 9.9.5 to 9.11.0.</h3>

:information_source: Keep your dependencies up-to-date. This makes it
easier to fix existing vulnerabilities and to more quickly identify and
fix newly disclosed vulnerabilities when they affect your project.

<hr/>


- The recommended version is **2 versions** ahead of your current
version.

- The recommended version was released **24 days ago**.




<details>
<summary><b>Release notes</b></summary>
<br/>
  <details>
    <summary>Package name: <b>pino</b></summary>
    <ul>
      <li>
<b>9.11.0</b> - <a
href="https://redirect.github.com/pinojs/pino/releases/tag/v9.11.0">2025-09-20</a></br><h2>What's
Changed</h2>
<ul>
<li>feat: added timestamp rfc3339 format with nanoseconds by <a
class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/edge33/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/edge33">@ edge33</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3288586845" data-permission-text="Title is private"
data-url="pinojs/pino#2251"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2251/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2251">#2251</a></li>
<li>fix: gracefully handle missing diagChannel.tracingChannel on Node
&lt; 18.19 by <a class="user-mention notranslate"
data-hovercard-type="user"
data-hovercard-url="/users/aryamohanan/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/aryamohanan">@ aryamohanan</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3433786084" data-permission-text="Title is private"
data-url="pinojs/pino#2290"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2290/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2290">#2290</a></li>
</ul>
<h2>New Contributors</h2>
<ul>
<li><a class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/edge33/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/edge33">@ edge33</a> made their first
contribution in <a class="issue-link js-issue-link"
data-error-text="Failed to load title" data-id="3288586845"
data-permission-text="Title is private"
data-url="pinojs/pino#2251"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2251/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2251">#2251</a></li>
<li><a class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/aryamohanan/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/aryamohanan">@ aryamohanan</a> made
their first contribution in <a class="issue-link js-issue-link"
data-error-text="Failed to load title" data-id="3433786084"
data-permission-text="Title is private"
data-url="pinojs/pino#2290"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2290/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2290">#2290</a></li>
</ul>
<p><strong>Full Changelog</strong>: <a class="commit-link"
href="https://redirect.github.com/pinojs/pino/compare/v9.10.0...v9.11.0"><tt>v9.10.0...v9.11.0</tt></a></p>
      </li>
      <li>
<b>9.10.0</b> - <a
href="https://redirect.github.com/pinojs/pino/releases/tag/v9.10.0">2025-09-17</a></br><h2>What's
Changed</h2>
<ul>
<li>docs: Move pino-logflare out of legacy transports list by <a
class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/kamilogorek/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/kamilogorek">@ kamilogorek</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3406229630" data-permission-text="Title is private"
data-url="pinojs/pino#2283"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2283/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2283">#2283</a></li>
<li>Add support for <code>Pear</code> and <code>Bare</code> runtimes by
<a class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/yassernasc/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/yassernasc">@ yassernasc</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3388452783" data-permission-text="Title is private"
data-url="pinojs/pino#2278"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2278/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2278">#2278</a></li>
<li>Add tracing channels by <a class="user-mention notranslate"
data-hovercard-type="user"
data-hovercard-url="/users/jsumners-nr/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/jsumners-nr">@ jsumners-nr</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3402802217" data-permission-text="Title is private"
data-url="pinojs/pino#2281"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2281/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2281">#2281</a></li>
<li>Add pino-console to ecoystem page by <a class="user-mention
notranslate" data-hovercard-type="user"
data-hovercard-url="/users/mcollina/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/mcollina">@ mcollina</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3426535226" data-permission-text="Title is private"
data-url="pinojs/pino#2288"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2288/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2288">#2288</a></li>
</ul>
<h2>New Contributors</h2>
<ul>
<li><a class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/kamilogorek/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/kamilogorek">@ kamilogorek</a> made
their first contribution in <a class="issue-link js-issue-link"
data-error-text="Failed to load title" data-id="3406229630"
data-permission-text="Title is private"
data-url="pinojs/pino#2283"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2283/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2283">#2283</a></li>
<li><a class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/yassernasc/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/yassernasc">@ yassernasc</a> made
their first contribution in <a class="issue-link js-issue-link"
data-error-text="Failed to load title" data-id="3388452783"
data-permission-text="Title is private"
data-url="pinojs/pino#2278"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2278/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2278">#2278</a></li>
<li><a class="user-mention notranslate" data-hovercard-type="user"
data-hovercard-url="/users/jsumners-nr/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/jsumners-nr">@ jsumners-nr</a> made
their first contribution in <a class="issue-link js-issue-link"
data-error-text="Failed to load title" data-id="3402802217"
data-permission-text="Title is private"
data-url="pinojs/pino#2281"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2281/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2281">#2281</a></li>
</ul>
<p><strong>Full Changelog</strong>: <a class="commit-link"
href="https://redirect.github.com/pinojs/pino/compare/v9.9.5...v9.10.0"><tt>v9.9.5...v9.10.0</tt></a></p>
      </li>
      <li>
<b>9.9.5</b> - <a
href="https://redirect.github.com/pinojs/pino/releases/tag/v9.9.5">2025-09-10</a></br><h2>What's
Changed</h2>
<ul>
<li>fix: allow object type in %s placeholder by <a class="user-mention
notranslate" data-hovercard-type="user"
data-hovercard-url="/users/mcollina/hovercard"
data-octo-click="hovercard-link-click"
data-octo-dimensions="link_type:self"
href="https://redirect.github.com/mcollina">@ mcollina</a> in <a
class="issue-link js-issue-link" data-error-text="Failed to load title"
data-id="3388093159" data-permission-text="Title is private"
data-url="pinojs/pino#2277"
data-hovercard-type="pull_request"
data-hovercard-url="/pinojs/pino/pull/2277/hovercard"
href="https://redirect.github.com/pinojs/pino/pull/2277">#2277</a></li>
</ul>
<p><strong>Full Changelog</strong>: <a class="commit-link"
href="https://redirect.github.com/pinojs/pino/compare/v9.9.4...v9.9.5"><tt>v9.9.4...v9.9.5</tt></a></p>
      </li>
    </ul>
from <a href="https://redirect.github.com/pinojs/pino/releases">pino
GitHub release notes</a>
  </details>
</details>

---

> [!IMPORTANT]
>
> - Check the changes in this PR to ensure they won't cause issues with
your project.
> - This PR was automatically created by Snyk using the credentials of a
real user.

---

**Note:** _You are seeing this because you or someone else with access
to this repository has authorized Snyk to open upgrade PRs._

**For more information:** <img
src="https://api.segment.io/v1/pixel/track?data=eyJ3cml0ZUtleSI6InJyWmxZcEdHY2RyTHZsb0lYd0dUcVg4WkFRTnNCOUEwIiwiYW5vbnltb3VzSWQiOiJlMGNmZDdhOS0yNzM2LTQ3ZDUtOTY5Ny1iYWZjYzg0MDk5ZDgiLCJldmVudCI6IlBSIHZpZXdlZCIsInByb3BlcnRpZXMiOnsicHJJZCI6ImUwY2ZkN2E5LTI3MzYtNDdkNS05Njk3LWJhZmNjODQwOTlkOCJ9fQ=="
width="0" height="0"/>

> - 🧐 [View latest project
report](https://app.snyk.io/org/bugbaredrums/project/cf9c5b42-a7d0-446f-a41c-275c56edf456?utm_source&#x3D;github&amp;utm_medium&#x3D;referral&amp;page&#x3D;upgrade-pr)
> - 📜 [Customise PR
templates](https://docs.snyk.io/scan-using-snyk/pull-requests/snyk-fix-pull-or-merge-requests/customize-pr-templates?utm_source=&utm_content=fix-pr-template)
> - 🛠 [Adjust upgrade PR
settings](https://app.snyk.io/org/bugbaredrums/project/cf9c5b42-a7d0-446f-a41c-275c56edf456/settings/integration?utm_source&#x3D;github&amp;utm_medium&#x3D;referral&amp;page&#x3D;upgrade-pr)
> - 🔕 [Ignore this dependency or unsubscribe from future upgrade
PRs](https://app.snyk.io/org/bugbaredrums/project/cf9c5b42-a7d0-446f-a41c-275c56edf456/settings/integration?pkg&#x3D;pino&amp;utm_source&#x3D;github&amp;utm_medium&#x3D;referral&amp;page&#x3D;upgrade-pr#auto-dep-upgrades)

[//]: #
'snyk:metadata:{"breakingChangeRiskLevel":null,"FF_showPullRequestBreakingChanges":null,"FF_showPullRequestBreakingChangesWebSearch":null,"customTemplate":{"variablesUsed":[],"fieldsUsed":[]},"dependencies":[{"name":"pino","from":"9.9.5","to":"9.11.0"}],"env":"prod","hasFixes":false,"isBreakingChange":false,"isMajorUpgrade":false,"issuesToFix":[],"prId":"e0cfd7a9-2736-47d5-9697-bafcc84099d8","prPublicId":"e0cfd7a9-2736-47d5-9697-bafcc84099d8","packageManager":"npm","priorityScoreList":[],"projectPublicId":"cf9c5b42-a7d0-446f-a41c-275c56edf456","projectUrl":"https://app.snyk.io/org/bugbaredrums/project/cf9c5b42-a7d0-446f-a41c-275c56edf456?utm_source=github&utm_medium=referral&page=upgrade-pr","prType":"upgrade","templateFieldSources":{"branchName":"default","commitMessage":"default","description":"default","title":"default"},"templateVariants":[],"type":"auto","upgrade":[],"upgradeInfo":{"versionsDiff":2,"publishedDate":"2025-09-20T13:03:07.987Z"},"vulns":[]}'
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants