[SourceKit] Report number of instructions executed since SourceKit was started in statistics request

[ahoppen]

To measure code completion performance, add an option to tell sourcekitd to count the number of instructions it executed for a code completion request.

Since this is counting the number of instructions executed by the entire process, this only works reliably if a single request is executed at a time. It is the client's responsibility to ensure that. For now, this is fine because the intended user of this option is the stress tester, which only issues a single request per SourceKit instance anyway.

---

Eventually, with swiftlang/swift-stress-tester#150 and swiftlang/swift-source-compat-suite#539 merged, this will allow us to time the duration code completion requests took in the stress tester and generate an analysis like the following.

Output

IMPORTANT:
All measurements printed by this script were done in number of number of
instructions. Measurements in seconds are computed assuming that all machines
execute the same number of instructions per second at all times, which is not
correct. Thus all measurements in seconds should be taken with extreme care.
As they scale linearly with the number of instructions, it is safe to compare
values in seconds output by this script.

---------- All CodeComplete requests ----------

Average: 3e+08 instr (ca. 0.048s)

Histogram:
< 8e+06 instr (ca.  0.001s): ***                                       6.1% (<   6.1%)
< 2e+07 instr (ca.  0.003s): **                                        5.1% (<  11.2%)
< 3e+07 instr (ca.  0.005s):                                           0.8% (<  11.9%)
< 7e+07 instr (ca.  0.010s): *******                                  13.0% (<  24.9%)
< 1e+08 instr (ca.  0.020s):                                           0.0% (<  24.9%)
< 3e+08 instr (ca.  0.040s): **                                        4.7% (<  29.6%)
< 5e+08 instr (ca.  0.080s): **************************************** 68.3% (<  98.0%)
< 1e+09 instr (ca.  0.160s):                                           0.5% (<  98.4%)
< 2e+09 instr (ca.  0.321s):                                           1.5% (<  99.9%)
< 4e+09 instr (ca.  0.642s):                                           0.1% (<  99.9%)
< 9e+09 instr (ca.  1.283s):                                           0.1% (< 100.0%)

---------- 10 slowest files for CodeComplete requests ----------

-- /Users/alex/swift-src/swift-source-compat-suite/project_cache/Dollar/Sources/Dollar.swift --

Average: 4e+08 instr (ca. 0.058s)

Histogram:
< 2e+07 instr (ca.  0.003s): *******                                  11.0% (<  11.0%)
< 3e+07 instr (ca.  0.005s): ****                                      6.2% (<  17.2%)
< 7e+07 instr (ca.  0.010s): ****                                      6.2% (<  23.3%)
< 1e+08 instr (ca.  0.020s):                                           0.0% (<  23.3%)
< 3e+08 instr (ca.  0.040s): *******                                  10.6% (<  33.9%)
< 5e+08 instr (ca.  0.080s): **************************************** 58.6% (<  92.5%)
< 1e+09 instr (ca.  0.160s): **                                        4.0% (<  96.5%)
< 2e+09 instr (ca.  0.321s): *                                         2.6% (<  99.1%)
< 4e+09 instr (ca.  0.642s):                                           0.4% (<  99.6%)
< 9e+09 instr (ca.  1.283s):                                           0.4% (< 100.0%)

-- /Users/alex/swift-src/swift-source-compat-suite/project_cache/Dollar/Sources/AutoBind.swift --

Average: 4e+08 instr (ca. 0.054s)

Histogram:
< 8e+06 instr (ca.  0.001s):                                           1.7% (<   1.7%)
< 2e+07 instr (ca.  0.003s):                                           0.9% (<   2.6%)
< 3e+07 instr (ca.  0.005s):                                           0.0% (<   2.6%)
< 7e+07 instr (ca.  0.010s): ****                                      8.4% (<  11.0%)
< 1e+08 instr (ca.  0.020s):                                           0.0% (<  11.0%)
< 3e+08 instr (ca.  0.040s): ***                                       7.1% (<  18.1%)
< 5e+08 instr (ca.  0.080s): **************************************** 80.4% (<  98.6%)
< 1e+09 instr (ca.  0.160s):                                           0.0% (<  98.6%)
< 2e+09 instr (ca.  0.321s):                                           1.4% (< 100.0%)

-- /Users/alex/swift-src/swift-source-compat-suite/project_cache/Dollar/Sources/AutoCurry.swift --

Average: 3e+08 instr (ca. 0.041s)

Histogram:
< 8e+06 instr (ca.  0.001s): *******                                  11.7% (<  11.7%)
< 2e+07 instr (ca.  0.003s): ****                                      7.2% (<  18.9%)
< 3e+07 instr (ca.  0.005s):                                           0.0% (<  18.9%)
< 7e+07 instr (ca.  0.010s): ************                             18.9% (<  37.8%)
< 1e+08 instr (ca.  0.020s):                                           0.0% (<  37.8%)
< 3e+08 instr (ca.  0.040s):                                           1.1% (<  38.9%)
< 5e+08 instr (ca.  0.080s): **************************************** 60.0% (<  98.8%)
< 1e+09 instr (ca.  0.160s):                                           0.0% (<  98.8%)
< 2e+09 instr (ca.  0.321s):  

[ahoppen]

swiftlang/swift-stress-tester#150
swiftlang/swift-source-compat-suite#539

@swift-ci Please SourceKit stress test

[ahoppen]

@swift-ci Please test

[ahoppen]

@swift-ci Please test Windows

[benlangmuir]

Since this is global anyway, have you considered adding it to the source.request.statistics request instead of doing it per-request? There are important cases you can't measure per-request like the AST built during an edit request, which happens asynchronously. You could still measure those by calling statistics before the edit and then again after the semantic update notification is received.

Alternatively, if we really need it to be per-request, I think we should wrap it in a dictionary to leave ourselves room for adding more statistics without affecting the top-level response dictionary.

{
  ... response ...
  key.statistics: {
    key.instruction_count: Int
  }
}

and make the key to enable it more generic, like key.enable_request_statistics.

[benlangmuir]

Nitpick: It's nice to write swift:: explicitly to ensure it matches the header declaration.

[ahoppen]

@benlangmuir I hadn’t thought about using the statistics request like that but that sounds like a good idea. We just need to make sure that the overhead of the statistics request doesn’t skew our measurements. I’ll see how much overhead the statistics request adds tomorrow. If the results are comparable, I’ll change it.

[ahoppen]

Using the statistics request was an excellent idea. Greatly simplified this PR and also didn’t make the changes in the stress tester much more complex.

I measured how much overhead the two statistics requests add to the instruction count and it appears to be negligible, as expected (average of the equivalent of 0.4ms, with some extremes going up to 3ms)

[ahoppen]

@swift-ci Please test

[ahoppen]

@swift-ci Please test Windows

[ahoppen]

@swift-ci Please test Windows

[ahoppen]

@swift-ci Please test Windows