1464506 - Add off-main thread IO Marker support to Gecko profiles

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement, P2)

Description

[Randell Jesup [:jesup] (needinfo me)]

We want to be able to track file IO in Gecko profiles.  

We can track either every instance of IO (open/read/write/close/etc), or summary values (amount of IO total or per-thread per sample).

This will primarily track per-IO markers, and count values will land as another bug.

This may have high overhead, so capturing this level of detail should be optional.  We may also want stacks for the captures, though that's less interesting due to most IO being proxied.

For detailed captures, we'll want the name (using an ID to distinguish two accesses to the same file in the profile), mode, flags, count for read/write (and result?).  We could also log open, and close + summary of per-file IO on the filehandle while it was open (lower overhead, but more bookkeeping).

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: First WIP of IO Marker support

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Moving to p3 because no activity for at least 24 weeks.
See https://github.com/mozilla/bug-handling/blob/master/policy/triage-bugzilla.md#how-do-you-triage for more information

Comment 3

[Greg Tatum [:gregtatum]]

Popping this back up to P1.

Comment 4

[Florian Quèze [:florian]]

(In reply to Randell Jesup [:jesup] from comment #0)

We may also want stacks for the captures, though that's less
interesting due to most IO being proxied.

The stack is very useful for mainthread I/O. I would assume it's less relevant when the I/O is done off main thread.

Will these new IO markers replace the existing mainthreadio markers we have from https://searchfox.org/mozilla-central/source/tools/profiler/gecko/ProfilerIOInterposeObserver.cpp ?

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

Attachment: First WIP of IO Marker support

Comment 6

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Apply iomarkers to all threads; optionally capture stacks WIP

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

Attachment: First WIP of IO Marker support

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

It at least builds with the current version of those patches

Comment 9

[Greg Tatum [:gregtatum]]

I took a stab at measuring the cost of capturing stacks. This was on a newer macbook.

The summary is:

Average:        17.17μs per stack
Median:         15.66μs per stack
Min:            10.31μs per stack
Max:            27.12μs per stack
Test runs:      73 for loops, with 1000 payloads each
Total payloads: 73000 payloads

Some raw runs looks like this:

!!! Generate 1000 markers with stack    20648μs
!!! Generate 1000 markers without stack 645μs
!!! Time per stack                      20.002509μs
!!! Percentage difference               3197%

!!! Generate 1000 markers with stack    21864μs
!!! Generate 1000 markers without stack 643μs
!!! Time per stack                      21.220645μs
!!! Percentage difference               3395%

!!! Generate 1000 markers with stack    22300μs
!!! Generate 1000 markers without stack 821μs
!!! Time per stack                      21.479177μs
!!! Percentage difference               2715%

!!! Generate 1000 markers with stack    22821μs
!!! Generate 1000 markers without stack 656μs
!!! Time per stack                      22.165099μs
!!! Percentage difference               3476%```

My methodology was to emit 1000 markers with stacks, and 1000 without for every UserTiming payload. I then visited cnn.com and observed the console spew.

https://gist.github.com/gregtatum/7b997816f7efcc7aefaf201d80d8f25a

Comment 10

[Greg Tatum [:gregtatum]]

:jesup What's the status of your existing work? Do you mind if I take this over? I'm actively working on surfacing this information in the profiler front-end right now. Specifically I'm looking at re-using the existing payloads we have, and here only surfacing the off the main thread io information.

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Greg Tatum [:gregtatum] from comment #10)

:jesup What's the status of your existing work? Do you mind if I take this over? I'm actively working on surfacing this information in the profiler front-end right now. Specifically I'm looking at re-using the existing payloads we have, and here only surfacing the off the main thread io information.

You absolutely can take it over... however I really would want to have IO information from any captured thread - anyone doing perf work on a subsystem that does it's IO off-main-thread needs that (and we want all IO off the main thread).

If you don't mind modifying an existing payload, you could add fields to IOMarker. The FileIOMarkers I made would let you untangle what IO is for what file; how much data was read/written, etc.

Comment 12

[Greg Tatum [:gregtatum]]

I filed Bug 1527340 for the payload, this bug will focus only on surfacing non-main thread io.

Comment 13

[Greg Tatum [:gregtatum]]

I'm taking myself of assignment here, and marking as P2, since I'm not planning on actively working on it at the moment.

Comment 14

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

3rd owner's the charm? 😅

I have started my own WIP independently from :jesup's (I had not noticed this bug then), I'll see if I can steal some ideas and/or code...

Comment 15

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - Improved StaticBaseProfilerStats, added max duration - r?canaltinova

Made StaticBaseProfilerStats a proper class, with more explicit types for measurements and printfs.
Also added the maximum duration in a set, which can be useful to see what the worst case of some code may be.

(Reminder: This code is not built by default, uncomment # define PROFILER_RUNTIME_STATS above to enable it.)

Comment 16

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - CorePS records the main thread id - r?canaltinova

Depends on D75758

Comment 17

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - profiler_add_marker_for_mainthread records markers from any thread into the main thread track - r?canaltinova

Some markers may be more useful when gathered into a single track, and the main thread is ideal because it's always present.

Depends on D75759

Comment 18

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - Optionally record the thread id where each FileIO happened - r?canaltinova

The FileIO marker may be recorded into the main thread, so we need to keep track of the thread in which the IO really happened (which may be a thread that's not even selected for profiling).

Depends on D75760

Comment 19

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - Output the thread id where the file IO happened - r?canaltinova

Depends on D75761

Comment 20

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - Statically check profiler feature numbers - r?canaltinova

Depends on D75762

Comment 21

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - Record FileIO markers on all threads - r?canaltinova

In addition to the existing "mainthreadio" feature, we now have:

• "fileio" to capture file I/O from other profiled threads.
• "fileioall" to also capture file I/O from all threads (even unregistered threads).
• "iostacks" to capture stack traces with any "io" marker.
  These are off by default, except for MOZ_PROFILER_STARTUP=1 profiling where they are on by default.

Depends on D75763

Comment 22

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - profiler_features_if_active{,_and_unpaused}() returns all features bits - r?canaltinova

Some functions may want to examine more than one feature at once, these function return everything (if the profiler is active, and optionally unpaused) so that only one call is needed.

Depends on D75763

Comment 23

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1464506 - profiler_is_active_and_thread_is_registered - r?canaltinova

This can be used while the profiler is running, to know if the current thread is registered -- regardless of whether it is actively profiled.
This will help distinguish registered but non-profiled threads from threads that are not even registered (e.g., OS-generated threads).

Depends on D76280

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f863906be04e
Improved StaticBaseProfilerStats, added max duration - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/339892cd9819
CorePS records the main thread id - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/e9840189646f
profiler_add_marker_for_mainthread records markers from any thread into the main thread track - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/5eea77f70d79
Optionally record the thread id where each FileIO happened - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/24bb053826c4
Output the thread id where the file IO happened - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/4951d6f0c780
Statically check profiler feature numbers - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/cda20d08c55f
profiler_features_if_active{,_and_unpaused}() returns all features bits - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/fec31ffa35bd
profiler_is_active_and_thread_is_registered - r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/5d723af3382f
Record FileIO markers on all threads - r=canaltinova

Comment 25

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/f863906be04e
https://hg.mozilla.org/mozilla-central/rev/339892cd9819
https://hg.mozilla.org/mozilla-central/rev/e9840189646f
https://hg.mozilla.org/mozilla-central/rev/5eea77f70d79
https://hg.mozilla.org/mozilla-central/rev/24bb053826c4
https://hg.mozilla.org/mozilla-central/rev/4951d6f0c780
https://hg.mozilla.org/mozilla-central/rev/cda20d08c55f
https://hg.mozilla.org/mozilla-central/rev/fec31ffa35bd
https://hg.mozilla.org/mozilla-central/rev/5d723af3382f