00:14dwlsalmeida[d]: By the way, do you guys have any idea where I should start investigating regarding the massive performance drop between the C version from one year ago and what we have now?
00:14dwlsalmeida[d]: we apparently went from 7s for the H.264 test suite, to 78s
00:15dwlsalmeida[d]: nothing I wrote justifies a 10x drop, whatever it is
00:16airlied[d]: in a release build?
00:17dwlsalmeida[d]: both debug builds
00:17airlied[d]: rust debug is usually a lot higher overhead, maybe perf record a run and see if anything stands out
00:18dwlsalmeida[d]: not 10x as much, and a release build doesn't fix it either :/
00:18airlied[d]: oh so it's still slow on release, yeah then it's probably perf record time
00:57gfxstrand[d]: I'd try perf first. The other thing I'd look at is if you're ending up with more pushbufs for some reason. You could stick in a little queue submit print for that.
00:59gfxstrand[d]: IDK why I think that's a thing that could happen. It just seems like it's worth checking.
01:06dwlsalmeida[d]: I have a separate pushbuf for the rust stuff
01:07airlied: you could also just stick time printfs at cmd buffer begin/end to rule that out
01:08dwlsalmeida[d]: What I am trying to say is that I have a separate allocation for the rust stuff, is this a problem ?
01:08dwlsalmeida[d]: I notice that when you say nv_push_new() it reuses the BO
01:08dwlsalmeida[d]: Which…I don’t think I do
01:08dwlsalmeida[d]: It’s probably reallocated on each frame
01:13dwlsalmeida[d]: I mean this btw:
01:13dwlsalmeida[d]: https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/31867/diffs?commit_id=e6dc5469650e019b8be9b0bd9bf9aef23f14be34
01:18airlied[d]: hmm yeah that might cause some overhead, in theory command buffers should be mostly recyclable using cmd pools and resets
01:19airlied[d]: also memcpying the whole thing seems suboptimal
01:49gfxstrand[d]: Yeah, that's extra memcpy but shouldn't be a problem. There's a better way to provide that function that doesn't involve extra rust stuff in the command buffer but we can get to that later.
03:10esdrastarsis[d]: nvidia announced rtx blackwell, now gsp firmware headache begins :blobcatnotlikethis:
03:19redsheep[d]: Assuming reviews don't say it's somehow terrible I am probably going to buy that 5090, looks quite appealing
04:53gfxstrand[d]: Any idea when they're going to be on the shelves?
04:54gfxstrand[d]: Jan 30 according to the press release.
04:55tiredchiku[d]: 5070ti looks like a solid option
04:55tiredchiku[d]: https://cdn.discordapp.com/attachments/1034184951790305330/1326051608647434250/960x0.jpg?ex=677e054c&is=677cb3cc&hm=cbb2ef5a5ebf30718e7c7bbf2e23b3ec42238ee15327a033476fd9dbecbd1dec&
04:55gfxstrand[d]: esdrastarsis[d]: Hopefully Ben has been working on it. He's on the inside now so there's a good chance he already has a branch.
04:56tiredchiku[d]: day one support :shocked_horse:
04:56gfxstrand[d]: 🤷🏻♀️
04:56gfxstrand[d]: I'm going to get one and eagerly await a branch
04:57gfxstrand[d]: The other question is when will we have PCIe 6.0 capable motherboards to plug it into.
04:59gfxstrand[d]: A while ago they were bragging that Blackwell would be PCIe 6.0 but I see no mention of it in the press release. Probably need to wait for more CES announcements.
05:00gfxstrand[d]: I also have no idea if I'm going to have any NVK/NAK fixing to do or not.
05:00gfxstrand[d]: Hopefully nothing major
05:01gfxstrand[d]: But we'll find out
05:03tiredchiku[d]: `4x PCIe 8-pin cables (adapter in box) OR 1x 600 W PCIe Gen 5 cable`
05:03tiredchiku[d]: for the 5090
05:03tiredchiku[d]: so, maybe pcie gen 5?
05:03tiredchiku[d]: maybe gen5 x16
05:08redsheep[d]: gfxstrand[d]: Is that confirmed for 5090? I only found something saying as much for 5080
05:08mhenning[d]: gfxstrand[d]: yeah, I was thinking about tinkering with the instruction encodings whenever we get a new disassembler
05:08redsheep[d]: And the specs list rtx blackwell as gen 5 x16, so new motherboards wouldn't be a thing
05:09tiredchiku[d]: https://cdn.discordapp.com/attachments/1034184951790305330/1326055044373680159/VYK0JYv.png?ex=677e087f&is=677cb6ff&hm=c4886bbede3703c719fd924f073196025b5ebbacb235310566556f692d1bfdf7&
05:09tiredchiku[d]: redsheep[d]:
05:09tiredchiku[d]: nvidia product page: https://www.nvidia.com/en-us/geforce/graphics-cards/50-series/rtx-5090/
05:10tiredchiku[d]: 5080 also on jan 30th
05:10tiredchiku[d]: 5070 family in feb
05:15redsheep[d]: Some of the specs look a little weird. Definitely waiting for reviews, even if I can get a decent price for my 4090 second hand
05:16tiredchiku[d]: somehow I'm still hung up on not wanting to sell the 3070
05:34gfxstrand[d]: Now with FP4!
05:35gfxstrand[d]: I'm not 100% sure what that is but I fear it might be 4-bit floats...
05:35gfxstrand[d]: Yeah, it is. 🙃
05:36airlied[d]: some nir work to do then? 🙂
05:41gfxstrand[d]: Likely we'll just add some sort of conversation instruction and treat the ops as unit. They're going to work on 8 at a time like DP4.
05:42gfxstrand[d]: At some point we probably need to do some work to nir_alu_type to support more things we've been chatting about bfloat16 for a while now.
05:43gfxstrand[d]: But also there's no SPIR-V support for FP4 yet (though I'm sure Jeff has a draft spec ready) so we may have some time.
05:45gfxstrand[d]: The problem is that once you get below 16 bits, no one can agree on the encoding. Even 16 has multiple variants: binary16 and bfloat16. 8 and 4 are way worse. I have no idea what Nvidia settled on. We'll have to figure that out.
05:46gfxstrand[d]: So we need more than "float" and "16 bits" in NIR.
05:46gfxstrand[d]: Which is really annoying
06:36karolherbst[d]: that's all going to be fun in regards to opt_algebraic anyway
07:58redsheep[d]: I tried to look around for how blackwell even does fp4 and for whatever reason it isn't easy to find, but it sounds like it either has 1 mantissa bit, or none at all, which is... interesting. It might not even have infinity or NaN either.
08:10tiredchiku[d]: > for whatever reason
08:11tiredchiku[d]: the gen has just been announced .-.
08:13__ad: hi, trying to fix a backlight issue on a recent lenovo legion, what i see until now is that edp "dpcd" data seems not correct. Is this pssobile ?
08:16__ad: i have DP_EDP_PWMGEN_BIT_COUNT = 8, DP_EDP_BACKLIGHT_BRIGHTNESS_MSB set to 1, but maximum calulated is 255, while display wants 4096 (12 bits)
08:16__ad: So suspecting on wrong dpcd info from the panel. Not sure if this could be possible.
08:32redsheep[d]: tiredchiku[d]: I mean, it's almost certainly the same format as the datacenter blackwell gpus that were announced 9 months ago...
08:37tiredchiku[d]: hm
08:37tiredchiku[d]: fair enough
09:03notthatclippy[d]: redsheep[d]: Dunno about this in particular but in general that's not a safe assumption to make. Our naming scheme sure is something, and GB20X is often closer to AD10X (previous consumer grade generation) than GB10X datacenter grade
09:09tiredchiku[d]: on an unrelated note
09:09tiredchiku[d]: capture sdk release when nvidia
09:10tiredchiku[d]: still 8.0.8, the header still doesn't have anything for egl nvfbc or pipewire nvfbc that was added in recent drivers
11:13tiredchiku[d]: gfxstrand[d]: is there any specific reason we order our memory types the way we do?
11:13tiredchiku[d]: radv seems to do
11:13tiredchiku[d]: 1) DEVICE_LOCAL | | |
11:13tiredchiku[d]: 2) | HOST_VISIBLE | HOST_COHERENT |
11:13tiredchiku[d]: 3) DEVICE_LOCAL | HOST_VISIBLE | HOST_COHERENT |
11:13tiredchiku[d]: 4) | HOST_VISIBLE | HOST_COHERENT | HOST_CACHED
11:13tiredchiku[d]: nvprop does something similar
11:14tiredchiku[d]: but NVK does
11:14tiredchiku[d]: [0] DEVICE_LOCAL
11:14tiredchiku[d]: [1] DEVICE_LOCAL | HOST_VISIBLE | HOST_COHERENT
11:14tiredchiku[d]: [2] HOST_VISIBLE | HOST_COHERENT | HOST_CACHED
11:15tiredchiku[d]: Hans (vkd3d-proton) says putting rebar early in the list is going to cause a lot of problems, not just in vkd3d-proton
11:19mohamexiety[d]: notthatclippy[d]: in this case in particular it's tricky because there is normal FP4 and there's the microscaling format stuff. it's safe to assume any new datacenter GPU will support both, but for consumer stuff it's.... yeah
11:20tiredchiku[d]: unrelated, can be closed:
11:20tiredchiku[d]: https://gitlab.freedesktop.org/mesa/mesa/-/issues/12326
11:20tiredchiku[d]: https://gitlab.freedesktop.org/mesa/mesa/-/issues/11177
12:37tiredchiku[d]: tiredchiku[d]: nvm I get it
15:18dwlsalmeida[d]: Any ideas what can cause that?
15:18dwlsalmeida[d]: ERROR: [Loader Message] Code 0 : setup_loader_term_phys_devs: Failed to detect any valid GPUs in the current config
15:18dwlsalmeida[d]: ERROR at ./vulkaninfo/./vulkaninfo.h:241:vkEnumeratePhysicalDevices failed with ERROR_INITIALIZATION_FAILED
15:18dwlsalmeida[d]: Being run with:
15:18dwlsalmeida[d]: #!/bin/sh
15:18dwlsalmeida[d]: MESA=$HOME/DEV/mesa-nvk/builddir/install \
15:18dwlsalmeida[d]: LD_LIBRARY_PATH=$MESA/lib64:$MESA/lib:$LD_LIBRARY_PATH \
15:18dwlsalmeida[d]: LIBGL_DRIVERS_PATH=$MESA/lib64/dri:$MESA/lib/dri \
15:18dwlsalmeida[d]: VK_ICD_FILENAMES=$MESA/share/vulkan/icd.d/nouveau_icd.x86_64.json \
15:18dwlsalmeida[d]: VK_ENABLE_BETA_EXTENSIONS=1 \
15:18dwlsalmeida[d]: exec "$@"
15:18dwlsalmeida[d]: It's not my machine, otherwise I'd figure this out myself instead of asking
15:19dwlsalmeida[d]: and I can't reproduce..
15:25tiredchiku[d]: check kernel module
15:35gfxstrand[d]: tiredchiku[d]: Aren't those the same, just without uncached GART? We can flip the last two if it helps games.
15:38gfxstrand[d]: notthatclippy[d]: I suspect it's safe in this case. Y'all don't tend to do engineering work twice and introduce divergences between consumer and data center that might result in a CUDA program producing different results. Not without a damn good reason, anyway. If they've decided on an FP4 format, I expect it'll be consistent.
15:38gfxstrand[d]: What is it? Now that I don't know. I've got my theories but I'll need to get my hands on either docs or hardware to really know.
15:47tiredchiku[d]: gfxstrand[d]: yeah, I'm not entirely sure
15:47tiredchiku[d]: might be best to leave it as is until we can figure out how to do uncached sysmem
15:47tiredchiku[d]: or until issues pertaining to it actually show up again
15:48redsheep[d]: I just hope the new world model recognizes that paperclips are less important than people
15:51redsheep[d]: I got a pretty good chuckle out of the guy introducing Jensen accidentally saying the self driving cars are self aware cars
15:53Jasper[m]: <redsheep[d]> "I just hope the new world..." <- I understood this reference
15:54karolherbst[d]: ... they also added FP6?
15:54karolherbst[d]: why would they do that ...
15:54karolherbst[d]: imagine the day vulkan gets a non pot data type into it's core added
15:59gfxstrand[d]: I don't want to think about non-POT data types...
15:59gfxstrand[d]: NIR is going to need some work before that'll be a thing.
16:00gfxstrand[d]: LLVM already tried to hand us 24-bit integers once.
16:01gfxstrand[d]: As for why? Well, sometimes 4 isn't enough, I guess. 🤷🏻♀️
16:02karolherbst[d]: yeah....
16:02karolherbst[d]: llvm is weird with that
16:02gfxstrand[d]: I suspect some of this stuff is pretty niche and added because some AI customer is buying enough GPUs that they get to ask for specific hardware.
16:02karolherbst[d]: for sure
16:03karolherbst[d]: I'll be happy once this is all finally over
16:03mohamexiety[d]: yeah all the weird FP data types are due to this
16:03gfxstrand[d]: Fp64 is wonky. Like, you get 5 per register and that little bit of perf is enough that they didn't just spring for 4x8? I find it hard to believe that that's going to be generally applicable.
16:04mohamexiety[d]: got to save on VRAM without giving brain damage to the AI I guess :KEKW:
16:04gfxstrand[d]: FP4 makes some sense anyway
16:04karolherbst[d]: how does FP4 make any sense
16:04karolherbst[d]: can you like only encode 4 numbers with it?
16:05gfxstrand[d]: But if there's one thing we've learned in the GPU world, it's that the tiny memory savings from NPOT isn't worth the bother.
16:05karolherbst[d]: I wonder if it's more of a cost efficiency thing, like in terms of perf/power
16:06gfxstrand[d]: karolherbst[d]: For a some models, 0 and +/-1 are enough.
16:06karolherbst[d]: yeah, but then why not just use ints and bitmask it or something
16:07gfxstrand[d]: Some AI people are playing around with binary
16:07gfxstrand[d]: karolherbst[d]: Even if it was i2, you'd still want a matrix multiply instruction.
16:08karolherbst[d]: mhhhhh
16:08karolherbst[d]: I guess at that point it doesn't matter because you already use all that die space for the stuff
16:08gfxstrand[d]: It's not just about memory. It's about ALU throughout. Gotta smash those numbers as fast as possible.
16:08mohamexiety[d]: also FP6 may actually be the microscale block format stuff now that I think about it (this one: https://www.opencompute.org/documents/ocp-microscaling-formats-mx-v1-0-spec-final-pdf)
16:09karolherbst[d]: yeah, but like.. INT4 matrix multiply still makes more sense to me than FP4 😄
16:09gfxstrand[d]: karolherbst[d]: Yeah and FP4 is cheap. It's literally just a lookup table at that point.
16:09karolherbst[d]: mhhhhhhhhh
16:09karolherbst[d]: actually....
16:09karolherbst[d]: uhhhhh
16:09karolherbst[d]: I had a realization
16:11gfxstrand[d]: There's are also some crazy formats some people have experimented with which are SNORM logarithmic, so it's basically just mantissa. They apparently work really well for 8-bit and smaller.
16:11karolherbst[d]: yeah, fair
16:13gfxstrand[d]: There's a lot of research that's gone into low-bit computation. It's just not had enough money behind it to be put into big hardware until now.
16:13karolherbst[d]: yeah...
16:14redsheep[d]: karolherbst[d]: If you don't encode NaN and infinity you can use all 4 bits to represent 16 actual values on fp4.
16:14karolherbst[d]: I'm surprised that fp4 has that many values
16:15gfxstrand[d]: gfxstrand[d]: Unfortunately, lots of academic research and experimentation doesn't lead to standardizing. The next few years are going to be interesting.
16:15karolherbst[d]: bfloat6 and float6
16:16gfxstrand[d]: Please no
16:17gfxstrand[d]: I'm hoping we get one or two standards for 4 and 8 and some interesting integer ops that give us 1-bit. I hope 6 dies.
16:17karolherbst[d]: well.. bfloat needs at least 9 bits anyway
16:17karolherbst[d]: bfloat9
16:17gfxstrand[d]: No
16:17gfxstrand[d]: We already have R11G11B10. That's enough damage.
16:17mohamexiety[d]: gfxstrand[d]: at least for AMD and NVIDIA, both seem to have standardized on the OCP formats which seems good for now
16:18karolherbst[d]: though bfloat9 would have no fraction part, so I think we need 10
16:21redsheep[d]: Watch as sentience is discovered to require 9 bits minimum and the AI overlords redesign all computers to have 9 bits to a byte
16:21gfxstrand[d]: If it is OCP then it's 1.2.1 with no inf/nan.
16:22gfxstrand[d]: Which makes sense. That's kinda what I guessed.
16:22karolherbst[d]: my big hope is, that there is yet to be money made in the biz if you aren't a hardware vendor
16:22karolherbst[d]: so maybe it just all implodes and we won't have to bother with those weirdo types
16:23redsheep[d]: Problem is some of the applications are very valid. This all isn't just going to go away, even if the delusional parts disappeared tomorrow
16:23karolherbst[d]: yeah, but then you don't need fp4 or so
16:23gfxstrand[d]: Oh, we need fp4
16:23karolherbst[d]: pain
16:24karolherbst[d]: guess fp6 is out the window then
16:24gfxstrand[d]: That's needed on the end device doing the inference. I expect we'll see it in Mali and similar very soon.
16:24karolherbst[d]: fair I guess
16:45gfxstrand[d]: On Nvidia, this shit exists for compatibility and so that you can train truly absurd models. On Mali, Intel, and whoever else, it exists so you can do inference in reasonable time without burning all your system resources (or at all, in that case if mobile).
19:47dwlsalmeida[d]: https://cdn.discordapp.com/attachments/1034184951790305330/1326276110823985295/perf_C.data?ex=677ed661&is=677d84e1&hm=28e688e33a77518b09b8e92ca8aa2ad8e4db4b7c44a29b6f7993193afedb92f3&
19:47dwlsalmeida[d]: https://cdn.discordapp.com/attachments/1034184951790305330/1326276111155593307/perf_rust.data?ex=677ed661&is=677d84e1&hm=747c87c9f91d48576cff1858229322be17e44c070e29bb313551b8739047abdb&
19:47dwlsalmeida[d]: Hey guys, I've never used perf before, I wonder if any of you can spot what is broken between these two?
19:48dwlsalmeida[d]: I am still trying to find why the newer Rust video stuff takes 10x longer
19:57dwlsalmeida[d]: ugh, the file is too large to send
20:07dwlsalmeida[d]: https://drive.google.com/file/d/1SIJEnwcUvbrq0AN2uxaXQxpQCbFE7cC1/view?usp=sharing
20:07dwlsalmeida[d]: https://drive.google.com/file/d/1_bsTqpRO6WkA7abd4S0ajc2fiDNZAOci/view?usp=sharing
20:21airlied[d]: not even sure how to use those files 🙂
20:21airlied[d]: normally perf record --call-graph dwarf <testapp> then perf report is my go to
20:35dwlsalmeida[d]: this is perf archive, so, IIUC, there's a perf.data inside, plus the dwaft business to make it portable/readable between machines
20:35dwlsalmeida[d]: anyways, I am looking through this with a more experienced colleague
20:35tanriol: A nice shareable (not sure about file size limits, however) option for perf is converting and uploading with Firefox Profiler https://profiler.firefox.com/docs/#/./guide-perf-profiling
20:36dwlsalmeida[d]: I don't think there's anything meaningful, apparently the CPU is idle most of the time, which may be us waiting on the fence for the frame currently being decoded?
20:37dwlsalmeida[d]: tanriol: so, `perf record --call-graph dwarf <testapp> `, then `perf script -g`?
20:38dwlsalmeida[d]: how do I share that, is it a matter of simply sharing the URL?
20:39airlied: I use perf report and you should be able to see the largest consumers
20:39airlied: but if it's actually just all in idle, then perf won't realy help
20:39tanriol: dwlsalmeida[d]: `perf script -F +pid` for converting and IIRC there should be an upload button somewhere in the top right corner
20:53dwlsalmeida[d]: C version ---> https://share.firefox.dev/4j4UusI
20:53dwlsalmeida[d]: Rust version -----> https://share.firefox.dev/4j6AHcb
20:55airlied: I think gst_element_set_state going higher is where I'd start
21:07dwlsalmeida[d]: gfxstrand[d]: airlied[d] what do you guys think about this?
21:07dwlsalmeida[d]: https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/31867/diffs#92b686abc64efd665e8e50b45fbab7f359761ca6_0_92
21:08dwlsalmeida[d]: all calls to vkCmdBeginVideoCodingKHR and vkCmdDecodeVideoKHR are serialized using this mutex
21:08dwlsalmeida[d]: I don't think this matters right? only if you were trying to record commands from multiple threads at once
21:08airlied: I think ffmpeg wants to do that
21:09dwlsalmeida[d]: ok, but do you think this mutex is related to the performance drop?
21:09dwlsalmeida[d]: just from initially looking at that code, that is
21:10airlied[d]: I doubt it, esp if gst is single thread
21:10dwlsalmeida[d]: it is
21:12gfxstrand[d]: Yeah, mutexes are cheap.
21:13airlied[d]: uncontested 🙂
21:17dwlsalmeida[d]: well, they are I think, unless you have multiple threads recording with the same VkVideoSession object at once
21:17dwlsalmeida[d]: which is not the case here
21:18dwlsalmeida[d]: alright, after a lot of this `perf` thing, we aren't any better :/
21:26airlied[d]: there is a definite difference in % for that fn above
21:27airlied[d]: just can't see perf samples in the driver there
21:31airlied[d]: if you search for a frame with nvk_CmdVideoDecodeKHR it seems to show a large diff
21:32dwlsalmeida[d]: ok, but (again IIUC), this is a tiny fraction of the CPU time anyways?
21:32airlied[d]: https://share.firefox.dev/3W49PzF vs https://share.firefox.dev/3W4a0ej
21:33airlied[d]: 12ms vs 140ms seems significant over a lot of frames
21:35dwlsalmeida[d]: sorry, where did you read the 140ms from?
21:36dwlsalmeida[d]: (not sure the page loaded right here)
21:43airlied[d]: oh click on the function
21:43airlied[d]: I clicked off it when I permalinked
21:44airlied[d]: I think just doing a printk timing around that one function would be enough to demonstrate it and help tell difference between debug/release as well
21:44airlied[d]: sorry printf time
21:45airlied[d]: since a lot of the overheads seesm to be rust not inlining
21:46airlied[d]: though the append is in there as well
21:51dwlsalmeida[d]: welp, but that doesn't explain why it's not much better on release builds
21:52dwlsalmeida[d]: but ok, let's try what you said
21:52dwlsalmeida[d]: also, I don't think Rust can inline across crates if you don't specifically `#[inline` stuff
21:53dwlsalmeida[d]: so, the push stuff is a crate, the video stuff is another crate, all calls into `nv_push_rs` are not inlined
21:54airlied[d]: sounds important to fix
21:54ndufresne: o/
21:56dwlsalmeida[d]: @ndufresne has been working with me to try and figure out what's happening
22:11mhenning[d]: dwlsalmeida[d]: fwiw, I always run perf on release builds - imo having compiler optimizations off distorts the results way more than missing some stack frames in the trace because of inlining
22:11mhenning[d]: or rather, release with debug info
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.029 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.005 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.004 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.004 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.003 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12airlied[d]: okay if the C speed is the same, them it seems unlikely
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:12dwlsalmeida[d]: I don't think the problem is here ^
22:14dwlsalmeida[d]: Ok, this rules out Rust btw
22:14dwlsalmeida[d]: this is the only function written in Rust basically
22:14dwlsalmeida[d]: unless the problem is actually flushing the Rust pushbuf to the GPU
22:15karolherbst[d]: looking at the graphs, it looks like the CPU waits mostly
22:15karolherbst[d]: so it's not like it's slower in terms of spent CPU cycles, but rather the CPU spends a lot of time in blocked state
22:15karolherbst[d]: (well the process rather)
22:16dwlsalmeida[d]: is it possible to say what exactly blocks? It's not the mutex thing otherwise it would show up in the thing I pasted above
22:17karolherbst[d]: `g_mutex_lock`?
22:17dwlsalmeida[d]: no, I am referring to the Rust mutex I placed before vkCmdBeginVideoCoding and vkCmdDecodeVideo
22:18dwlsalmeida[d]: this `g_mutex_lock` is some gstreamer lock somewhere else
22:18karolherbst[d]: yeah, but it's most likely the thing it blocks on
22:19karolherbst[d]: could also be `nvcmd_ctx_wait`
22:19karolherbst[d]: it's kinda weird, bcause it seems to be various things,
22:19karolherbst[d]: but anyway
22:19karolherbst[d]: the process is clearly not doing anything a lot of time
22:20karolherbst[d]: (it's the blue bar in the process/thread view)
22:20karolherbst[d]: well..
22:20karolherbst[d]: it's not a bar if the CPU doesn't do anything
22:21karolherbst[d]: looks like it happens roughly ever 5ms
22:22karolherbst[d]: it's executing stuff for like 0.1ms then 5ms of nothing
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.029 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000090 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000060 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:23dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.001 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000080 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000090 ms
22:23dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:23karolherbst[d]: yeah....
22:23karolherbst[d]: it doesn't feel like it's actually something in the process
22:23karolherbst[d]: but something else messing
22:24karolherbst[d]: you can zoom into those blue segments
22:25karolherbst[d]: but you can see it in both traces if you zoom in close enough
22:26karolherbst[d]: but maybe there was also a problem of doing the trace
22:26karolherbst[d]: dunno
22:27karolherbst[d]: anyway, profiling is hard and should only be done with release builds
22:28dwlsalmeida[d]: well, the client has to wait on the fence associated with the `VkImage` containing the decoded data
22:28dwlsalmeida[d]: I wonder if...that's not related?
22:29dwlsalmeida[d]: although I did not touch that at all
22:31karolherbst[d]: kinda want to trace all related processes at the same time to really see what's going on probably. But if there is a GPU in the mix it's getting a bit more complicated to trace it properly and see where it blocks on
22:34dwlsalmeida[d]: ok, this is how long we have to wait in the Rust version before the VkImage is ready:
22:34dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000080 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:34dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.448 ms
22:34dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000010 ms
22:34dwlsalmeida[d]: Redistribute latency...
22:34dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.457 ms
22:34dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000010 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:34dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.460 ms
22:34dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:34dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000040 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000010 ms
22:35dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.450 ms
22:35dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000080 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000040 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000020 ms
22:35dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.448 ms
22:35dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000040 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000010 ms
22:35dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 1.104 ms
22:35dwlsalmeida[d]: nvk_CmdDecodeVideoKHR execution time: 0.002 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000070 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000030 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000050 ms
22:35dwlsalmeida[d]: nvkmd_ctx_wait execution time: 0.000010 ms
22:35dwlsalmeida[d]: lets see the C version now
22:35Ermine: did you pipe your stuff into discord?
22:35HdkR: cat dmesg > discord
22:36DodoGTA: Ermine: That's definitely a text snippet from Discord
22:36Ermine: ah, indeed
22:36HdkR: That's some amazingly bad integration from the bot
22:37karolherbst[d]: yeah.... that part is kinda weird, but not sure there are many options besides automatically uploading it to some pastebin website
22:37HdkR: Isn't that what matrix does?
22:38Ermine: matrix hosts its own pastebin
22:39dwlsalmeida[d]: dwlsalmeida[d]: ```
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.526 ms
22:39dwlsalmeida[d]: Redistribute latency...
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.452 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.449 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.456 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.477 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.457 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.118 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.398 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.459 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.456 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.455 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.462 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.462 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.462 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.453 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.458 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.118 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.119 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.119 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.117 ms
22:39dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.118 ms
22:39dwlsalmeida[d]: eeh...looks similar?
22:39Jasper[m]: Yeah the matrix bot does not enjoy that
22:40dwlsalmeida[d]: sorry guys,
22:40dwlsalmeida[d]: will pastebin stuff from now on
22:40HdkR: Ermine: Sounds like the discord both needs to host its own pastebin as well then :P
22:40HdkR: discord bot*
22:42dwlsalmeida[d]: actually..not really..we seem to take longer in the Rust version
22:44dwlsalmeida[d]: plenty of frames like this in the C code:
22:44dwlsalmeida[d]: gst_vulkan_operation_wait execution time: 0.116 ms
22:44dwlsalmeida[d]: but literally no frame takes less than `0.450` in the Rust version
22:52asdqueerfromeu[d]: dwlsalmeida[d]: Does that mean that Rust bäd? /s
22:53redsheep[d]: That still doesn't quite account for a 10x difference
22:53redsheep[d]: At least it doesn't look like it would
22:54dwlsalmeida[d]: so total wait time is `151ms` vs `72ms`
22:55dwlsalmeida[d]: still far off from 10x worse
23:17dwlsalmeida[d]: ok, finally some progress
23:18dwlsalmeida[d]: @ndufresne
23:18dwlsalmeida[d]: vkh26adec output_picture execution time: 0.197 ms
23:18dwlsalmeida[d]: vs
23:18dwlsalmeida[d]: vkh26adec output_picture execution time: 5.423 ms
23:19orowith2os[d]: `#[inline]` everything 🔥 /j
23:20dwlsalmeida[d]: sometimes as much as 7ms per frame
23:21dwlsalmeida[d]: yeah, the C version is consistent at 0.2 per frame
23:24dwlsalmeida[d]: I'll leave this to some other day, but for whatever reason `gst_video_decoder_finish_frame`is taking much more time
23:24dwlsalmeida[d]: maybe `uftrace` can help here