Skip to content

Optimise tracing timestamp formatting to reduce logging overhead #7232

@jimmygchen

Description

@jimmygchen

See this comment: #7168 (comment)

let timestamp = Local::now().format("%Y-%m-%d %H:%M:%S").to_string();

We currently use this approach Local::now().format() for formatting timestamp in 3 places in logging, and this format function seems relatively expensive - it adds up significantly given it gets called very frequently.

UPDATE: My initial grep command was incorrect, and it picked up some other packages too, have updated the command and numbers below. Thanks @pawanjay176 for raising it.

I did a brief profiling and it showed that ~11.44% ~5.90% of total CPU time is spent in chrono formatting functions, if I calculated correctly:

$ grep '$chrono' lighthouse_2025-03-31-182111.collapsed | wc -l
736
$ wc -l lighthouse_2025-03-31-182111.collapsed
12468 lighthouse_2025-03-31-182111.collapsed

Might be worth optimising a bit here, e.g. consider alternatives, e.g. StrftimeItems or the time crate.

I made an attempt using StrftimeItems and it's showing much better results (~~~3.58%~~ ~1.5% overhead) - although still quite high just for logging timestamp formatting.
macladson#6

Metadata

Metadata

Assignees

No one assigned

    Labels

    UX-and-logsoptimizationSomething to make Lighthouse run more efficiently.v7.1.0Post-Electra release

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions