Negative profile measurements on MacOS

[Davidster]

I am seeing that sometimes query_result.time.end - query_result.time.start gives me a negative value on mac. Have you seen this before? I could create a mini repo that reproduces the problem if you'd like :).

[Wumpf]

Yes, this is sort of a known issue, see linebender/vello#475 (comment)

I figure though wgpu_profiler could do some mitigation here:

• better document the problem
• warn when negative results come in / invalidate them programmatically

The render/compute pass centric API should not have this issue btw.!

[Davidster]

thanks, I will give that a read. what do you mean by the render/compute pass centric API?

[Wumpf]

scoped_render_pass and scoped_compute_pass
These are the only two entry points supported in WebGPU actually by now (still gated by a feature flag) - this is not reflected in wgpu 0.19 yet but will be in the next wgpu release

[Davidster]

Ah I see.. I'm afraid my application is (only) using scoped_render_pass already though

[Wumpf]

uhoh! Then wgpu is likely more buggy than I thought this is, will have to look into this

[Wumpf]

Interested in that mini-repo now. Might be a good starting point. Xcode frame debugger should be able to point out where the time stamp queries go and how that's wrong

[Davidster]

I'll see if I can whip something up tonight

[Davidster]

I was actually able to reproduce this with the wgpu profiler demo. Just ran cargo run --example demo. I changed the logging a bit in my fork to make it more obvious: https://github.com/Davidster/wgpu-profiler/tree/negative_timestamps_logging.

here's what I got. The times where the 'rendering' scope went into the negative was when I opened up the app switcher.

[examples/demo.rs:68:5] adapter.features() = Features(
    DEPTH_CLIP_CONTROL | TIMESTAMP_QUERY | INDIRECT_FIRST_INSTANCE | SHADER_F16 | BGRA8UNORM_STORAGE | FLOAT32_FILTERABLE | RG11B10UFLOAT_RENDERABLE | DEPTH32FLOAT_STENCIL8 | TEXTURE_COMPRESSION_BC | TEXTURE_COMPRESSION_ETC2 | TEXTURE_COMPRESSION_ASTC | TEXTURE_FORMAT_16BIT_NORM | TEXTURE_COMPRESSION_ASTC_HDR | TEXTURE_ADAPTER_SPECIFIC_FORMAT_FEATURES | MAPPABLE_PRIMARY_BUFFERS | TEXTURE_BINDING_ARRAY | STORAGE_RESOURCE_BINDING_ARRAY | SAMPLED_TEXTURE_AND_STORAGE_BUFFER_ARRAY_NON_UNIFORM_INDEXING | UNIFORM_BUFFER_AND_STORAGE_TEXTURE_ARRAY_NON_UNIFORM_INDEXING | MULTI_DRAW_INDIRECT | PUSH_CONSTANTS | ADDRESS_MODE_CLAMP_TO_ZERO | ADDRESS_MODE_CLAMP_TO_BORDER | POLYGON_MODE_LINE | VERTEX_WRITABLE_STORAGE | CLEAR_TEXTURE | SHADER_UNUSED_VERTEX_OUTPUT | SHADER_PRIMITIVE_INDEX | DUAL_SOURCE_BLENDING,
)
No profiling results available yet!
Got negative time for scope render pass bottom: -19158763.271ms
Got negative time for scope render pass bottom: -19158763.271ms
Got negative time for scope render pass bottom: -20.227ms
Got negative time for scope render pass bottom: -19158812.855ms
Got negative time for scope render pass bottom: -44.057ms
Got negative time for scope render pass bottom: -59.577ms
Got negative time for scope render pass bottom: -47.609ms
Got negative time for scope render pass bottom: -48.838ms
Got negative time for scope render pass bottom: -48.801ms
Got negative time for scope render pass bottom: -48.767ms
Got negative time for scope render pass bottom: -48.956ms
Got negative time for scope render pass bottom: -49.067ms
Got negative time for scope render pass bottom: -48.919ms
Got negative time for scope render pass bottom: -48.934ms
Got negative time for scope render pass bottom: -48.878ms
Got negative time for scope render pass bottom: -48.906ms
Got negative time for scope render pass bottom: -48.908ms
Got negative time for scope render pass bottom: -49.148ms
Got negative time for scope render pass bottom: -48.835ms
Got negative time for scope render pass bottom: -50.496ms
Got negative time for scope render pass bottom: -49.982ms
Got negative time for scope render pass bottom: -50.888ms
Got negative time for scope render pass bottom: -47.313ms
Got negative time for scope render pass bottom: -47.949ms
Got negative time for scope render pass bottom: -50.249ms
Got negative time for scope render pass bottom: -47.757ms
Got negative time for scope render pass bottom: -48.121ms
Got negative time for scope render pass bottom: -49.284ms
Got negative time for scope render pass bottom: -48.247ms
Got negative time for scope render pass bottom: -48.914ms
Got negative time for scope render pass bottom: -49.019ms
Got negative time for scope render pass bottom: -48.857ms
Got negative time for scope render pass bottom: -49.149ms
Got negative time for scope render pass bottom: -48.637ms
Got negative time for scope render pass bottom: -48.430ms
Got negative time for scope render pass bottom: -48.916ms
Got negative time for scope render pass bottom: -49.627ms
Got negative time for scope render pass bottom: -48.838ms
Got negative time for scope render pass bottom: -48.749ms
Got negative time for scope render pass bottom: -48.616ms
Got negative time for scope render pass bottom: -48.701ms
Got negative time for scope render pass bottom: -48.852ms
Got negative time for scope render pass bottom: -48.890ms
Got negative time for scope render pass bottom: -48.424ms
Got negative time for scope render pass bottom: -48.461ms
Got negative time for scope render pass bottom: -48.810ms
Got negative time for scope render pass bottom: -47.944ms
Got negative time for scope render pass bottom: -49.123ms
Got negative time for scope render pass bottom: -48.587ms
Got negative time for scope render pass bottom: -49.598ms
Got negative time for scope render pass bottom: -49.021ms
Got negative time for scope render pass bottom: -49.062ms
Got negative time for scope render pass bottom: -48.772ms
Got negative time for scope render pass bottom: -48.857ms
Got negative time for scope render pass bottom: -48.448ms
Got negative time for scope render pass bottom: -48.830ms
Got negative time for scope render pass bottom: -48.837ms
Got negative time for scope render pass bottom: -48.843ms
Got negative time for scope render pass bottom: -48.870ms
Got negative time for scope render pass bottom: -48.441ms
Got negative time for scope render pass bottom: -48.918ms
Got negative time for scope render pass bottom: -48.998ms
Got negative time for scope render pass bottom: -48.460ms
Got negative time for scope render pass bottom: -49.123ms
Got negative time for scope render pass bottom: -49.237ms
Got negative time for scope render pass bottom: -48.730ms
Got negative time for scope render pass bottom: -48.631ms
Got negative time for scope render pass bottom: -48.833ms
Got negative time for scope render pass bottom: -48.622ms
Got negative time for scope render pass bottom: -48.509ms
Got negative time for scope render pass bottom: -48.401ms
Got negative time for scope render pass bottom: -49.594ms
Got negative time for scope render pass bottom: -49.550ms
Got negative time for scope render pass bottom: -48.455ms
Got negative time for scope render pass bottom: -48.202ms
Got negative time for scope render pass bottom: -47.909ms
Got negative time for scope render pass bottom: -49.135ms
Got negative time for scope render pass bottom: -49.076ms
Got negative time for scope render pass bottom: -48.914ms
Got negative time for scope render pass bottom: -48.837ms
Got negative time for scope render pass bottom: -48.962ms
Got negative time for scope render pass bottom: -48.884ms
Got negative time for scope render pass bottom: -48.845ms
Got negative time for scope render pass bottom: -49.046ms
Got negative time for scope render pass bottom: -48.170ms
Got negative time for scope render pass bottom: -39.965ms
Got negative time for scope render pass bottom: -31.547ms
Got negative time for scope render pass bottom: -23.659ms
Got negative time for scope render pass bottom: -32.919ms
Got negative time for scope render pass bottom: -48.370ms
Got negative time for scope render pass bottom: -48.661ms
Got negative time for scope render pass bottom: -48.486ms
Got negative time for scope render pass bottom: -48.772ms
Got negative time for scope render pass bottom: -49.076ms
Got negative time for scope render pass bottom: -49.551ms
Got negative time for scope render pass bottom: -49.466ms
Got negative time for scope render pass bottom: -47.784ms
Got negative time for scope render pass bottom: -49.140ms
Got negative time for scope render pass bottom: -48.419ms
Got negative time for scope render pass bottom: -49.697ms
Got negative time for scope render pass bottom: -48.392ms
Got negative time for scope render pass bottom: -48.378ms
Got negative time for scope render pass bottom: -49.630ms
Got negative time for scope render pass bottom: -48.645ms
Got negative time for scope render pass bottom: -81.600ms
Got negative time for scope render pass bottom: -79.206ms
Got negative time for scope render pass bottom: -96.553ms
Got negative time for scope render pass bottom: -65.552ms
Got negative time for scope render pass bottom: -49.043ms
Got negative time for scope render pass bottom: -48.810ms
Got negative time for scope render pass bottom: -48.901ms
Got negative time for scope render pass bottom: -48.717ms
Got negative time for scope render pass bottom: -48.912ms
Got negative time for scope render pass bottom: -48.759ms
Got negative time for scope render pass bottom: -48.782ms
Got negative time for scope render pass bottom: -48.659ms
Got negative time for scope render pass bottom: -48.890ms
Got negative time for scope render pass bottom: -48.837ms
Got negative time for scope render pass bottom: -49.071ms
Got negative time for scope render pass bottom: -48.903ms
Got negative time for scope render pass bottom: -49.000ms
Got negative time for scope render pass bottom: -48.783ms
Got negative time for scope render pass bottom: -48.837ms
Got negative time for scope render pass bottom: -48.914ms
Got negative time for scope render pass bottom: -48.893ms
Got negative time for scope render pass bottom: -48.828ms
Got negative time for scope render pass bottom: -48.868ms
Got negative time for scope render pass bottom: -48.824ms
Got negative time for scope render pass bottom: -48.943ms
Got negative time for scope render pass bottom: -48.759ms
Got negative time for scope render pass bottom: -48.829ms
Got negative time for scope render pass bottom: -48.773ms
Got negative time for scope render pass bottom: -48.992ms
Got negative time for scope render pass bottom: -48.908ms
Got negative time for scope render pass bottom: -48.956ms
Got negative time for scope render pass bottom: -48.777ms
Got negative time for scope render pass bottom: -48.831ms
Got negative time for scope render pass bottom: -48.851ms
Got negative time for scope render pass bottom: -48.872ms
Got negative time for scope render pass bottom: -48.830ms
Got negative time for scope render pass bottom: -48.932ms
Got negative time for scope render pass bottom: -48.813ms
Got negative time for scope render pass bottom: -48.761ms
Got negative time for scope render pass bottom: -48.914ms
Got negative time for scope render pass bottom: -48.901ms
Got negative time for scope render pass bottom: -48.855ms
Got negative time for scope render pass bottom: -48.765ms
Got negative time for scope render pass bottom: -48.856ms
Got negative time for scope render pass bottom: -48.826ms
Got negative time for scope render pass bottom: -48.811ms
Got negative time for scope render pass bottom: -48.765ms
Got negative time for scope render pass bottom: -48.910ms
Got negative time for scope render pass bottom: -48.939ms
Got negative time for scope render pass bottom: -48.951ms
Got negative time for scope render pass bottom: -48.926ms
Got negative time for scope render pass bottom: -48.839ms
Got negative time for scope render pass bottom: -48.770ms
Got negative time for scope render pass bottom: -48.946ms
Got negative time for scope render pass bottom: -48.834ms
Got negative time for scope render pass bottom: -48.936ms
Got negative time for scope render pass bottom: -48.857ms
Got negative time for scope render pass bottom: -48.871ms
Got negative time for scope render pass bottom: -48.780ms
Got negative time for scope render pass bottom: -48.840ms
Got negative time for scope render pass bottom: -48.881ms
Got negative time for scope render pass bottom: -48.855ms
Got negative time for scope render pass bottom: -48.884ms
Got negative time for scope render pass bottom: -48.886ms
Got negative time for scope render pass bottom: -48.924ms
Got negative time for scope render pass bottom: -48.784ms
Got negative time for scope render pass bottom: -48.785ms
Got negative time for scope render pass bottom: -48.761ms
Got negative time for scope render pass bottom: -48.895ms
Got negative time for scope render pass bottom: -48.749ms
Got negative time for scope render pass bottom: -48.944ms
Got negative time for scope render pass bottom: -48.626ms
Got negative time for scope render pass bottom: -48.856ms
Got negative time for scope render pass bottom: -48.752ms
Got negative time for scope render pass bottom: -48.998ms
Got negative time for scope render pass bottom: -48.890ms
Got negative time for scope render pass bottom: -48.974ms
Got negative time for scope render pass bottom: -48.855ms
Got negative time for scope render pass bottom: -48.895ms
Got negative time for scope render pass bottom: -48.882ms
Got negative time for scope render pass bottom: -49.007ms
Got negative time for scope render pass bottom: -48.894ms
Got negative time for scope render pass bottom: -48.751ms
Got negative time for scope render pass bottom: -48.886ms
Got negative time for scope render pass bottom: -48.789ms
Got negative time for scope render pass bottom: -48.886ms
Got negative time for scope render pass bottom: -48.781ms
Got negative time for scope render pass bottom: -48.901ms
Got negative time for scope render pass bottom: -48.802ms
Got negative time for scope render pass bottom: -48.829ms
Got negative time for scope render pass bottom: -48.895ms
Got negative time for scope render pass bottom: -48.897ms
Got negative time for scope render pass bottom: -48.937ms
Got negative time for scope render pass bottom: -48.769ms
Got negative time for scope render pass bottom: -48.920ms
Got negative time for scope render pass bottom: -48.785ms
Got negative time for scope render pass bottom: -48.834ms
Got negative time for scope render pass bottom: -48.828ms
Got negative time for scope render pass bottom: -48.871ms
Got negative time for scope render pass bottom: -48.869ms
Got negative time for scope render pass bottom: -48.890ms
Got negative time for scope render pass bottom: -48.973ms
Got negative time for scope render pass bottom: -48.940ms
Got negative time for scope render pass bottom: -48.848ms
Got negative time for scope render pass bottom: -48.844ms
Got negative time for scope render pass bottom: -48.839ms
Got negative time for scope render pass bottom: -48.904ms
Got negative time for scope render pass bottom: -48.774ms
Got negative time for scope render pass bottom: -48.842ms
Got negative time for scope render pass bottom: -48.828ms
Got negative time for scope render pass bottom: -48.841ms
Got negative time for scope render pass bottom: -48.809ms
Got negative time for scope render pass bottom: -48.870ms
Got negative time for scope render pass bottom: -48.848ms
Got negative time for scope render pass bottom: -48.806ms
Got negative time for scope render pass bottom: -48.834ms
Got negative time for scope render pass bottom: -49.015ms
Got negative time for scope render pass bottom: -48.846ms
Got negative time for scope render pass bottom: -48.356ms
Got negative time for scope render pass bottom: -41.081ms
Got negative time for scope render pass bottom: -26.416ms
Got negative time for scope render pass bottom: -48.895ms
Got negative time for scope render pass bottom: -48.536ms
Got negative time for scope render pass bottom: -48.379ms
Got negative time for scope render pass bottom: -49.512ms
Got negative time for scope render pass bottom: -48.570ms
Got negative time for scope render pass bottom: -49.535ms
Got negative time for scope rendering: -49.873ms
Got negative time for scope render pass bottom: -48.825ms
Got negative time for scope render pass bottom: -47.930ms
Got negative time for scope render pass bottom: -48.834ms
Got negative time for scope render pass bottom: -49.154ms
Got negative time for scope render pass bottom: -48.655ms
Got negative time for scope render pass bottom: -47.362ms
Got negative time for scope render pass bottom: -48.928ms
Got negative time for scope render pass bottom: -46.955ms
Got negative time for scope render pass bottom: -49.895ms
Got negative time for scope render pass bottom: -48.919ms
Got negative time for scope render pass bottom: -49.350ms
Got negative time for scope render pass bottom: -48.334ms
Got negative time for scope render pass bottom: -49.211ms
Got negative time for scope render pass bottom: -48.310ms
Got negative time for scope render pass bottom: -48.001ms
Got negative time for scope render pass bottom: -48.159ms
Got negative time for scope render pass bottom: -49.320ms
Got negative time for scope render pass bottom: -49.060ms
Got negative time for scope render pass bottom: -49.149ms
Got negative time for scope render pass bottom: -49.148ms
Got negative time for scope render pass bottom: -49.248ms
Got negative time for scope render pass bottom: -48.211ms
Got negative time for scope render pass bottom: -48.214ms
Got negative time for scope render pass bottom: -49.055ms
Got negative time for scope render pass bottom: -48.996ms
Got negative time for scope render pass bottom: -48.217ms
Got negative time for scope render pass bottom: -48.381ms
Got negative time for scope render pass bottom: -48.685ms
Got negative time for scope render pass bottom: -49.901ms
Got negative time for scope render pass bottom: -49.192ms
Got negative time for scope render pass bottom: -49.314ms
Got negative time for scope render pass bottom: -48.994ms
Got negative time for scope render pass bottom: -49.509ms
Got negative time for scope render pass bottom: -49.351ms
Got negative time for scope render pass bottom: -49.043ms
Got negative time for scope render pass bottom: -48.702ms
Got negative time for scope render pass bottom: -49.286ms
Got negative time for scope render pass bottom: -48.788ms
Got negative time for scope render pass bottom: -48.570ms
Got negative time for scope render pass bottom: -48.519ms
Got negative time for scope render pass bottom: -48.353ms
Got negative time for scope rendering: -51.837ms
Got negative time for scope render pass bottom: -47.955ms
Got negative time for scope render pass bottom: -48.950ms
Got negative time for scope render pass bottom: -49.190ms
Got negative time for scope render pass bottom: -48.849ms
Got negative time for scope render pass bottom: -48.136ms
Got negative time for scope render pass bottom: -48.059ms
Got negative time for scope rendering: -50.926ms
Got negative time for scope render pass bottom: -49.136ms
Got negative time for scope rendering: -50.161ms
Got negative time for scope render pass bottom: -80.132ms
Got negative time for scope render pass bottom: -78.748ms
Got negative time for scope render pass bottom: -77.884ms
Got negative time for scope render pass bottom: -48.907ms
Got negative time for scope render pass bottom: -49.069ms
Got negative time for scope render pass bottom: -48.915ms
Got negative time for scope render pass bottom: -48.826ms
Got negative time for scope render pass bottom: -48.865ms
Got negative time for scope render pass bottom: -48.787ms
Got negative time for scope render pass bottom: -48.808ms
Got negative time for scope render pass bottom: -48.944ms
Got negative time for scope render pass bottom: -48.853ms
Got negative time for scope render pass bottom: -48.827ms
Got negative time for scope render pass bottom: -48.821ms
Got negative time for scope render pass bottom: -48.883ms
Got negative time for scope render pass bottom: -48.880ms
Got negative time for scope render pass bottom: -48.304ms
Got negative time for scope render pass bottom: -40.336ms
Got negative time for scope render pass bottom: -18.666ms
Got negative time for scope render pass bottom: -30.808ms
Got negative time for scope render pass bottom: -47.633ms
Got negative time for scope render pass bottom: -49.280ms
Got negative time for scope render pass bottom: -49.077ms
Got negative time for scope render pass bottom: -48.052ms
Got negative time for scope render pass bottom: -48.176ms
Got negative time for scope render pass bottom: -48.936ms
Got negative time for scope render pass bottom: -49.882ms
Got negative time for scope render pass bottom: -48.663ms
Got negative time for scope render pass bottom: -48.765ms
Got negative time for scope render pass bottom: -47.467ms
Got negative time for scope render pass bottom: -48.740ms
Got negative time for scope render pass bottom: -48.662ms
Got negative time for scope render pass bottom: -49.020ms
Got negative time for scope render pass bottom: -48.245ms
Got negative time for scope render pass bottom: -48.178ms
Got negative time for scope render pass bottom: -49.492ms
Got negative time for scope render pass bottom: -49.262ms
Got negative time for scope render pass bottom: -48.567ms
Got negative time for scope render pass bottom: -49.041ms
Got negative time for scope render pass bottom: -48.907ms
Got negative time for scope render pass bottom: -49.234ms
Got negative time for scope render pass bottom: -48.952ms
Got negative time for scope render pass bottom: -48.333ms
Got negative time for scope render pass bottom: -48.937ms
Got negative time for scope render pass bottom: -49.104ms
Got negative time for scope render pass bottom: -48.920ms
Got negative time for scope render pass bottom: -48.942ms
Got negative time for scope render pass bottom: -48.770ms
Got negative time for scope render pass bottom: -48.564ms
Got negative time for scope render pass bottom: -48.921ms
Got negative time for scope render pass bottom: -50.122ms
Got negative time for scope render pass bottom: -46.641ms
Got negative time for scope render pass bottom: -48.860ms
Got negative time for scope render pass bottom: -49.262ms
Got negative time for scope render pass bottom: -49.480ms
Got negative time for scope render pass bottom: -79.778ms
Got negative time for scope render pass bottom: -79.750ms
Got negative time for scope render pass bottom: -78.218ms
Got negative time for scope render pass bottom: -48.813ms
Got negative time for scope render pass bottom: -48.866ms
Got negative time for scope render pass bottom: -49.112ms
Got negative time for scope render pass bottom: -48.935ms
Got negative time for scope render pass bottom: -48.999ms
Got negative time for scope render pass bottom: -48.766ms
Got negative time for scope render pass bottom: -48.880ms
Got negative time for scope render pass bottom: -48.808ms
Got negative time for scope render pass bottom: -48.817ms
Got negative time for scope render pass bottom: -48.798ms
Got negative time for scope render pass bottom: -48.765ms
Got negative time for scope render pass bottom: -48.817ms
Got negative time for scope render pass bottom: -48.865ms
Got negative time for scope render pass bottom: -48.838ms
Got negative time for scope render pass bottom: -48.959ms
Got negative time for scope render pass bottom: -48.809ms
Got negative time for scope render pass bottom: -48.867ms
Got negative time for scope render pass bottom: -48.870ms
Got negative time for scope render pass bottom: -48.853ms
Got negative time for scope render pass bottom: -48.808ms
Got negative time for scope render pass bottom: -48.863ms
Got negative time for scope render pass bottom: -48.888ms
Got negative time for scope render pass bottom: -48.833ms
Got negative time for scope render pass bottom: -48.912ms
Got negative time for scope render pass bottom: -48.896ms
Got negative time for scope render pass bottom: -48.888ms
Got negative time for scope render pass bottom: -48.907ms
Got negative time for scope render pass bottom: -48.828ms
Got negative time for scope render pass bottom: -48.525ms
Got negative time for scope render pass bottom: -48.628ms
Got negative time for scope render pass bottom: -48.740ms
Got negative time for scope render pass bottom: -49.089ms
Got negative time for scope render pass bottom: -48.994ms
Got negative time for scope render pass bottom: -48.881ms
Got negative time for scope render pass bottom: -48.925ms
Got negative time for scope render pass bottom: -48.981ms
Got negative time for scope render pass bottom: -48.954ms
Got negative time for scope render pass bottom: -48.788ms
Got negative time for scope render pass bottom: -49.025ms
Got negative time for scope render pass bottom: -48.956ms
Got negative time for scope render pass bottom: -48.943ms
Got negative time for scope render pass bottom: -48.862ms
Got negative time for scope render pass bottom: -48.816ms
Got negative time for scope render pass bottom: -48.883ms