noverify
noverify copied to clipboard
VKCOM
Very slow analysis of certain files in WordPress
Code Example
File wp-includes/sodium_compat/src/Core32/Curve25519.php is just 3000 lines of code and takes 22 seconds analyse:
$ git clone https://github.com/WordPress/WordPress.git
...
$ noverify -allow-checks=none -debug-parse-duration=1s .
2020/09/17 16:16:36.214426 built without version info (try using 'make install'?)
2020/09/17 16:16:36.238748 Started
2020/09/17 16:16:36.470106 Indexing [.]
2020/09/17 16:16:36.625121 Linting
2020/09/17 16:16:45.102624 Parsing of wp-includes/sodium_compat/src/Core32/X25519.php took 7.738661974s
2020/09/17 16:16:59.718856 Parsing of wp-includes/sodium_compat/src/Core32/Curve25519.php took 22.357586981s
Actual Behavior
The file with 3k lines takes 22 seconds to analyse.
Expected Behavior
3k lines should be analysed in ~100 ms or less.
The file that takes 22 seconds to parse: https://github.com/WordPress/WordPress/blob/master/wp-includes/sodium_compat/src/Core32/Curve25519.php
Also, from Laravel empty project (after being installed via composer create-project --prefer-dist laravel/laravel blog):
> ~/go/bin/noverify -allow-checks=none -debug-parse-duration=1s . 6179 ms
2020/09/17 16:48:05.752932 built without version info (try using 'make install'?)
2020/09/17 16:48:05.785647 Started
2020/09/17 16:48:06.006290 Indexing [.]
...
2020/09/17 16:48:06.738534 Linting
...
2020/09/17 16:48:13.641547 Parsing of vendor/phpunit/phpunit/src/TextUI/TestRunner.php took 6.558489826s
TestRunner.php is just 1300 sloc, the times are consistent across runs.
This file should be very close to the one from Laravel: https://github.com/sebastianbergmann/phpunit/blob/master/src/TextUI/TestRunner.php
I ran the file https://github.com/WordPress/WordPress/blob/master/wp-includes/sodium_compat/src/Core32/Curve25519.php with the profiler. The linter is engaged in iterating over TypesMap 74% of the time (60% of which is engaged in sorting and another 40% in calling the callback).
Below are the top 50 functions and the Iterate function.
Save New Duplicate & Edit Just Text
Showing nodes accounting for 25.27s, 87.26% of 28.96s total
Dropped 329 nodes (cum <= 0.14s)
Showing top 50 nodes out of 151
flat flat% sum% cum cum%
7.89s 27.24% 27.24% 7.89s 27.24% cmpbody
2.75s 9.50% 36.74% 2.75s 9.50% aeshashbody
1.92s 6.63% 43.37% 10.29s 35.53% sort.doPivot
1.48s 5.11% 48.48% 3.73s 12.88% runtime.scanobject
1.32s 4.56% 53.04% 4.72s 16.30% runtime.mapassign_faststr
1.17s 4.04% 57.08% 2.20s 7.60% runtime.mapaccess2_faststr
1.12s 3.87% 60.95% 1.36s 4.70% runtime.findObject
0.56s 1.93% 62.88% 0.56s 1.93% runtime.memmove
0.48s 1.66% 64.54% 0.85s 2.94% runtime.greyobject
0.46s 1.59% 66.13% 8.49s 29.32% sort.StringSlice.Less
0.44s 1.52% 67.65% 2.30s 7.94% runtime.mallocgc
0.43s 1.48% 69.13% 1.97s 6.80% runtime.evacuate_faststr
0.43s 1.48% 70.61% 0.48s 1.66% runtime.heapBitsSetType
0.43s 1.48% 72.10% 0.78s 2.69% sort.insertionSort
0.40s 1.38% 73.48% 0.40s 1.38% runtime.memclrNoHeapPointers
0.39s 1.35% 74.83% 0.39s 1.35% memeqbody
0.39s 1.35% 76.17% 0.39s 1.35% runtime.stdcall2
0.26s 0.9% 77.07% 6.75s 23.31% github.com/VKCOM/noverify/src/solver.(*resolver).resolveType
0.24s 0.83% 77.90% 1.63s 5.63% github.com/VKCOM/noverify/src/meta.wrap
0.24s 0.83% 78.73% 0.24s 0.83% runtime.markBits.isMarked (inline)
0.18s 0.62% 79.35% 6.13s 21.17% github.com/VKCOM/noverify/src/solver.(*resolver).resolveTypeNoLateStaticBinding
0.17s 0.59% 79.94% 0.23s 0.79% runtime.spanOf (inline)
0.16s 0.55% 80.49% 0.16s 0.55% runtime.stdcall4
0.15s 0.52% 81.01% 0.15s 0.52% runtime.strhash
0.14s 0.48% 81.49% 0.22s 0.76% runtime.mapiternext
0.14s 0.48% 81.98% 0.33s 1.14% sort.medianOfThree
0.13s 0.45% 82.42% 0.20s 0.69% github.com/VKCOM/noverify/src/meta.unwrap2
0.12s 0.41% 82.84% 0.25s 0.86% runtime.mapaccess2
0.10s 0.35% 83.18% 21.37s 73.79% github.com/VKCOM/noverify/src/meta.TypesMap.Iterate <----------------------------------
0.10s 0.35% 83.53% 0.28s 0.97% runtime.mapassign
0.10s 0.35% 83.87% 11.24s 38.81% sort.quickSort
0.09s 0.31% 84.19% 1.52s 5.25% encoding/gob.(*Decoder).compileDec
0.09s 0.31% 84.50% 0.21s 0.73% runtime.gcWriteBarrier
0.08s 0.28% 84.77% 1.01s 3.49% runtime.newobject (partial-inline)
0.08s 0.28% 85.05% 0.20s 0.69% runtime.typedmemmove
0.07s 0.24% 85.29% 2.26s 7.80% github.com/VKCOM/noverify/src/solver.exprTypeLocalCustom.func1
0.07s 0.24% 85.53% 0.21s 0.73% runtime.sweepone
0.06s 0.21% 85.74% 0.55s 1.90% github.com/VKCOM/noverify/src/meta.slice
0.05s 0.17% 85.91% 0.48s 1.66% runtime.lock2
0.05s 0.17% 86.08% 0.63s 2.18% runtime.makemap_small
0.05s 0.17% 86.26% 0.72s 2.49% runtime.makeslice
0.04s 0.14% 86.40% 0.32s 1.10% runtime.(*mcentral).cacheSpan
0.04s 0.14% 86.53% 3.74s 12.91% runtime.gcDrain
0.03s 0.1% 86.64% 0.39s 1.35% encoding/gob.(*Decoder).compatibleType
0.03s 0.1% 86.74% 1.19s 4.11% encoding/gob.(*Decoder).decOpFor
0.03s 0.1% 86.84% 6.84s 23.62% github.com/VKCOM/noverify/src/solver.(*resolver).resolveTypes.func1
0.03s 0.1% 86.95% 0.45s 1.55% runtime.(*mcache).nextFree
0.03s 0.1% 87.05% 0.20s 0.69% runtime.(*mheap).allocSpan
0.03s 0.1% 87.15% 0.23s 0.79% runtime.schedule
0.03s 0.1% 87.26% 0.17s 0.59% runtime.wbBufFlush1
Iterate:
Total: 28.96s
ROUTINE ======================== github.com/VKCOM/noverify/src/meta.TypesMap.Iterate in C:\projects\noverify\src\meta\typesmap.go
100ms 21.37s (flat, cum) 73.79% of Total
. 90ms 386: keys := make([]string, 0, len(m.m))
10ms 220ms 387: for k := range m.m {
30ms 30ms 388: keys = append(keys, k)
. . 389: }
. . 390:
. 11.24s 391: sort.Strings(keys)
. . 392:
50ms 50ms 393: for _, k := range keys {
10ms 9.74s 394: cb(k)
. . 395: }
. . 396:}
Ok, so what is the reason why it spends so much time there? There is no clear reason why the types map should become so big.