MobileNativeFoundation / XCLogParser

Tool to parse Xcode and xcodebuild logs stored in the xcactivitylog format
Apache License 2.0
1.73k stars 121 forks source link

swiftFunctionTimes not always populated in certain cases #47

Closed mobileben closed 4 years ago

mobileben commented 4 years ago

I recently turned on swift timings (-driver-time-compilation -Xfrontend -debug-time-compilation -Xfrontend -debug-time-function-bodies -Xfrontend -debug-time-expression-type-checking) and noticed a couple of things.

This happens when using Cocoapods. Some of the pods build by using a single CompileSwift step with all swift files as arguments (versus individual CompileSwift steps per file). This results in a Build Summary that looks like this:

Screen Shot 2019-12-12 at 10 52 34 PM

as opposed to something like this:

Screen Shot 2019-12-13 at 2 59 20 PM

This results in the signature for the step being "CompileSwift normal x86_64" versus something like "CompileSwift normal x86_64 source.swift". In other words, it is lacking the source file name.

The commandDetailDesc from the dump does contain the actual swift files (along with the other flags). I also can see that the text field contains what looks like the swift timing information. It appears xclogparse probably uses the signature and the existence of a source in the signature as the cue when to generate swiftFunctionTimes.

ecamacho commented 4 years ago

We haven't tested it with cocoa pods. I will do some tests with it, is there any specific pod that is causing this issue?

I'll take a look at the parsing speeds, I may be able to make it faster.

mobileben commented 4 years ago

@ecamacho It seems like the issue is building Swift modules with as "Whole Modules" versus "Incremental".

Not sure why, but for some reason the project I'm working on has all their Swift pods doing this. When set back to Incremental, the individual file compilation continues.

Based on what dump contains, you should be able to extract at least the swiftFunctionTimes. Not sure if it's worth trying to list out all the swift files being compiled within the signature in that case (although maybe a qualifier and another array field would be helpful).

Oh, as one very minor thing. I just upgraded to a 2019 MBP which has Catalina. I'm not overly familiar with rake, but Catalina now defaults Terminal to zsh. So as a temp work around till I understand it better I used alias rake="noglob rake" prior to invoking. Adding a note about this for the build instructions would be helpful.

ecamacho commented 4 years ago

@mobileben feel free to test this PR https://github.com/spotify/XCLogParser/pull/48 I'm parsing the swift files that were compiled and I also speed up the parsing times.

mobileben commented 4 years ago

@ecamacho I will test this shortly.

mobileben commented 4 years ago

@ecamacho quick question here. When should swiftFunctionTimes show up? I have a slightly different build configuration, but am using the correct flags. I can see the generated Swift build times listed in Xcode's Build summary. But when I run xclogparser on it with the parse argument and json reporter, all the swiftFunctionTimes are empty. The dump shows them.

This is using the current master.

I'm going to try and build again, but this time apply the flag across the pods.

I'll try and take a look at the XCLogParser code to see if I can gain any insights. And I'm going to try the branch with the fix since it takes so long to process using master. To give you an idea, the dump JSON is 848MB. So that should give you a relative sense of how large the xcactivitylogs are.

mobileben commented 4 years ago

Okay update.

Regarding the swift function fix. There is much improvement. The fixed version takes a 1-2 minutes (I did not precisely time). The current master took 1 hour and 15 minutes to process. Nice job on speeding it up!

I do notice if I run a diff, the results between master and swift_func_improv don't match. I haven't had a chance to take a closer look (because the generated files are large) to see if they are just out of order.

Also regarding not finding populated swiftFunctionTimes, I think I either ran into another issue or its working as intended. It appears if you use the the --redacted flag, then the swiftFunctionTimes are ... well redacted :D (ie. they don't show up).

That sort of seems like weird behavior since I would have just expected the filename to be redacted only where needed, like it is done elsewhere.

Oh yeah, this behavior is present in both master and swift_func_improv.

ecamacho commented 4 years ago

Hi, thanks for testing.

Yeah, the order can be different because it's now parsing in parallel the swift function times data. I've fixed the issue about not having the swift function time when you use the --redacted flag, nice catch. I've pushed the change to the swift_func_improv branch

mobileben commented 4 years ago

--redacted now has the swiftFunctionTimes.

Just curious, I notice a couple odd things (not related to xclogparser and was curious if you had any thoughts or insights.

Also, regarding that last question. I do notice that the time cited by Build Summary are sometimes smaller than what xclogparser kicks out. So in that example of 150 seconds, I might seen an extra 1-2 seconds on what is shown in the output of xclogparser. Have you noticed any strange behavior like this before?

ecamacho commented 4 years ago

Hi

I'll close this ticket, but feel free to open more issues, your feedback was really helpful.