UBA remote compiles taking much longer than the traces indicate

Development Pipeline & Plugins
, ,
1

We are experiencing an issue where UBA is end-to-end times for compilation units are much higher than the process info would indicate. We are currently on 5.6 but running fresh binaries from the UE P4 depot as of 4/27/26. Since I am limited to 4500 characters, I’ve attached the full process info for one of these compilation units, but here is the major relevant time information with any negligible times cut out:

 Module.SlateCore.2.cpp (Compile [x64])
 ProcessId: 113
 Start:   16.4s
 Duration: 6m34s

 ----------- Detours stats -----------
 Total          127  134.0s
 WaitOnResponse     119   23.4s
 Host              23.4s
 ...
 CreateFile        75   1.5s
 ...
 ListDirectory       4   21.9s
 Log            1   <1ms
 SendFiles         1  110.5s
 ...
 Startup Time           63ms
 Exit Time           110.6s
 DetoursMem           2.4mb
 IopsRead             173
 IopsOther             210
 PeakProcessMem (Win)      1.4gb
 PeakJobMem (Win)        1.4gb
 PeakMem             1.4gb
 CPU Time            43.4s
 Wall Time            56.9s
 ...
 SendCas          3  117.1s
   Bytes Raw/Comp  19.0mb   4.2mb
   Compress        5   48ms

[Attachment Removed]

2

Steps to Reproduce
N/A

[Attachment Removed]

3

I’m not fully following. Are you saying this step took longer than 6m34s?

The Detours stats is not the same as the total time of the process if that is what you meant. Those numbers are mostly to be able to understand overhead but that is also not really true “CreateFile” as an example contains stuff that actually make the detoured process CreateFile faster.

Based on ListDirectory it seems like your host machine is not super responsive and overloaded.

[Attachment Removed]

4

Yes, there should be documentation somewhere to help understand what the information mean.. but meanwhile, here are some short things

“Detours stats” - These are essentially timers around calls that go from detoured process (cl.exe etc) to host process. So cl.exe calls “CreateFile”, detoured code calls host process with a timer around it. ListDirectory is the same. The process calls FindFirstFile/FindNextFile etc, the timer is around the call to the host process.

If a “Total” detoured time takes 10seconds and Duration of process is 6 minutes.. then it simply means that the program itself spends 5min50seconds on doing whatever it is doing… totally unrelated to uba. To say that UBA’s “overhead” is 10 seconds is not exactly correct because those timers would have ended up being kernel calls instead… so the overhead is less than 10s.. but for the sake of simplicity we can say UBA had an overhead of 10 seconds.

“Session stats” - This is the time spent on some things inside the host process when called through Detours stats… so in your picture above, “ListDirectory” was called 4 times and took 21.9 seconds.. on the host process side this turned into 4 ListDirMsg (networked messages to the server) which took 8.9s…

“Storage stats” - kind of same as session stats but for the storage.

As an example

CreateFileW is called from cl.exe, enters UBA’s code (UbaDetours.dll) instead of kernel

UbaDetours.dll do CreateFile rpc to host process (UbaAgent.exe in this case)

UbaAgent.exe might send a “GetFileMsg” to get the hash of the file it wants to open

If UbaAgent does not have the file it then call EnsureCas which will download the file from the UBT process

So the time spent in CreateFile is an accumulated value of multiple things inside Storage and Session stats.

Kernel stats is timers around the actual calls to the kernel.

The time spent in the XxMsg under session stats is directly affected by network latency/bandwidth but also how busy the server is… it is impossible for me to say which one it is. It is strange that GetFileMsg is quite fast and ListDirMsg is slow.. maybe if I had the full .uba file I would be able to give some hints on where to look.

Sending files back to the server seems extremely slow. it takes 117 seconds to send 4.2mb… either it is network or the server is just choked. On our build farm our build machines often don’t manage to keep up and stall like crazy on I/O… that usually cause numbers like this. We are using some AWS instances with only 250mb/s write speed and low IOPS.. so usually the build machines is the bottleneck.

[Attachment Removed]

5

I took a look at the trace and here’s what I see.

Network seems very unstable (wifi or something). I see long stalls where there is no network traffic at all. Most helpers basically just wait to recv or send data. “Ping” is a small network message that basically just send/recv a few bytes. On Tipu machine it takes 90 seconds to get a response at one point

It is all networking issues afai can see. On a healthy build the yellow graph line (cpu usage) should be high on the helpers, in this case they are all at a couple percent most of the time.

Given that ping is sometimes ok (I’ve seen ~80ms at best.. but often 10-100 seconds) it seems like it is bandwidth or stability that is the problem. At Epic these kind of scenarios has been seen when communication goes through VPN or WIFI. (Or on Mac if heavy heavy cpu load on host)

You can test disabling pch, they are crazy bandwidth hogs but I still think it will not solve your problem.. there are actions in your build that takes 3 minutes to transfer 4mb from helper to host.

[Attachment Removed]

6

“The Detours stats is not the same as the total time of the process if that is what you meant.”

I guess that’s what is tripping me up. If the timing information doesn’t show me the entirety of where that 6m34s end-to-end time came from, how can I triage and correct the problem without a lot of guess work? Also, is there documentation anywhere with how to read this information and what various times may indicate, like what you suggest with ListDirectory possibly meaning the host machine is overloaded and how we would treat that? Is it a storage problem? RAM? Processor?

Ultimately the problem is that we run into situations where a compile that would take under a minute locally ends up taking up to 10m remotely and we can’t tell why because the break down in the info doesn’t account for most of that time. FWIW, I thought that in the case that there were remote compiles underway and the local cores are idle they would then basically “race” to complete the work rather than just continuing to twiddle their digits, but I guess not?

[Attachment Removed]

7

Thanks for all this info Henrik, that is incredibly enlightening and thorough! :slight_smile: Very appreciated!

This gives me some stuff to dig into on our end. I’ve attached the full .uba (as .txt, because it won’t let me attach .uba files :grin:) in case you want to poke at it and see if it sheds any enlightenment. I wonder if it would be possible to run something akin to PerfMon as part of UBA that then gets uploaded to the server so you can investigate where a node might be bottle necking? Probably not as an All The Time thing but maybe via a flag or something. Could be useful!

[Attachment Removed]