dump versus parse time durations

[mobileben]

I was analyzing my build using xclogparser invoked with parse --reporter json. As a test, I focused on one type == target. This had 22 defined subSteps. My thought was that the duration of the target should equal the sum of the durations of the subSteps. Each of these sub steps did not have any other sub steps.

Summing the sub steps results in a value of 1.0292 whereas the duration value for the target was defined as 5.7726 (I rounded these down)

I took at a look of the Xcode build output for the file I parsed. I did happen to notice that the steps that Xcode listed as 0.1 seconds were actually must smaller values. My guess is they just round up to 0.1 seconds. For example 0.007 sec appears to be rounded up to 0.1 sec. Unfortunately the total time for this target was not displayed in Xcode.

The time disparity is quite large. So I ran a dump to see if any clues could be found there. I found the same matching signature in the dump. I also verified the individual subSections from the dump matched the subSteps defined in the parse export to help verify I was looking at the same data.

I also wrote another script to do the math from the dump and got the same values.

Any thoughts on where that extra time came from? Should I expect summing the sub steps/ sub sections to match the target's duration time? Is the xcactivitylog missing information or is something being dropped on the floor?

Or am I looking at the data the wrong way where really the total time should be the target's duration plus the sum of the subStep durations? And if this is the case, how does one classify what "work" is being done by the target?

We're trying to optimize our build and find the places where we are slow, but it is a little unsettling to see a target's duration be so far off from it's subSteps

Thanks!

[mobileben]

Quick addition here. I looked over the subSteps a little better. One thing I notice is that there is actually a gap between them. For example, I see a jump from one section stopping at 597803329.65822005 and then the next on starting at 597803334.31234396.

Looking at it this way, the start time of the target is roughly equal to the start time of the first section and the ending time of the target is roughly equal to the end time of the last target.

I do have parallel builds turned off. But I think despite this Xcode does still do some things concurrently.

Does one chalk up gaps related to the OS or to Xcode scheduling something else?

[ecamacho]

Hi, yeah we use the start time of the first substep and the endtime of the last substep to compute the duration of the target. It would be more visible if you generate the timeline of the project using --reporter html. You may found interesting data with the html report, such as having a target that it took 30 seconds, but if you click on it to open the substeps you may realise that the compiler finished to compile all the files in 3 seconds and the linking was done after waiting for 26 seconds.

This can be up to parallelisation as you mentioned, but even with that turned-off Xcode is still doing some work concurrently. The other reason could be due to your build graph, that the linker is waiting for a dependency to be ready or a build-phase script is waiting for an input to be ready. You will need to gig more to know why those gaps between steps are happening and try to optimise them.

If you just want the actual compilation time, you can grab only the steps with type swiftCompilation and calculate those.

I'll double check that the target duration is accurately computed according to the substeps.