dnrops
/
swift-nio
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Update documentation related to allocation troubleshooting on Linux and the ability to run unit tests in parallel. (#1796) 

Motivation:

It's not obvious how to do analysis of allocation regressions on Linux, so some documentation would be helpful.
The run time for the unit tests can be quite long (a couple of minutes), can be cut down significantly if running tests in parallel, adding a hint about that.

Modification:

Updated documentation.

Result:

Easier to troubleshoot mallocs on Linux and faster running of unit tests.
This commit is contained in:
Joakim Hassila 2021-04-09 12:49:48 +02:00 committed by GitHub
parent f63571296d
commit 22b58cebee
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 129 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
README.md
View File

@ -353,3 +353,10 @@ dnf install swift-lang /usr/bin/nc /usr/bin/lsof /usr/bin/shasum
[repo-nio-ssl]: https://github.com/apple/swift-nio-ssl
[repo-nio-transport-services]: https://github.com/apple/swift-nio-transport-services
[repo-nio-ssh]: https://github.com/apple/swift-nio-ssh
### Speeding up testing
It's possible to run the test suite in parallel, it can save significant time if you have a larger multi-core machine, just add `--parallel` when running the tests. This can speed up the run time of the test suite with 30x or more.
```
swift test --parallel
```

122
docs/debugging-allocations.md
View File

@ -311,3 +311,125 @@ before: 10000, after: 20000
```
Now we see there's another stacktrace in the `AFTER` section which has no corresponding stacktrace in `BEFORE`. From the stack we can see it's originating from `doRequests(group:number:)`. In this instance we were working on options applied in this function so it appears we have added allocations. We have also increased the number of allocations which are reported in the different numbers section where stack traces have been paired but with different numbers of allocations.
### Debugging with 'heaptrack' (Linux)
Unfortunately we don't have dtrace or Instruments on Linux, but there is the [heaptrack](https://github.com/KDE/heaptrack) tool which supports diff analysis of two versions.
Tested on Ubuntu 20.04 (and likely working on other distributions) Install it with:
```
sudo apt-get install heaptrack
```
Then using the instructions previously, you need to build the test without hooks such that heaptrack can hook instead, e.g.:
```
cd IntegrationTests/tests_04_performance/test_01_resources/
./run-nio-alloc-counter-tests.sh -- -n test_1000_autoReadGetAndSet.swift
```
and then cd to the temp directory from the output (find the tmp directory as above), e.g.:
```
cd /tmp/.nio_alloc_counter_tests_5jMMhk
```
Finally, run the binary with heaptrack two times — first we do it for `main` to get a baseline:
```
ubuntu@ip-172-31-25-161 /t/.nio_alloc_counter_tests_GRusAy> SWIFTNIO_URING_DISABLED=1 heaptrack .build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
heaptrack output will be written to "/tmp/.nio_alloc_counter_tests_GRusAy/heaptrack.test_1000_autoReadGetAndSet.84341.gz"
starting application, this might take some time...
SWIFTNIO_URING_DISABLED set, disabling liburing.
test_1000_autoReadGetAndSet.total_allocations: 0
test_1000_autoReadGetAndSet.total_allocated_bytes: 0
test_1000_autoReadGetAndSet.remaining_allocations: 0
DEBUG: [["total_allocations": 0, "total_allocated_bytes": 0, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocated_bytes": 0, "total_allocations": 0], ["total_allocations": 0, "total_allocated_bytes": 0, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocated_bytes": 0, "total_allocations": 0], ["remaining_allocations": 0, "total_allocated_bytes": 0, "total_allocations": 0], ["remaining_allocations": 0, "total_allocations": 0, "total_allocated_bytes": 0], ["total_allocated_bytes": 0, "total_allocations": 0, "remaining_allocations": 0], ["total_allocated_bytes": 0, "total_allocations": 0, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 0, "total_allocated_bytes": 0], ["total_allocations": 0, "remaining_allocations": 0, "total_allocated_bytes": 0]]
free(): invalid pointer
Aborted (core dumped)
heaptrack stats:
allocations: 319347
leaked allocations: 107
temporary allocations: 68
Heaptrack finished! Now run the following to investigate the data:
heaptrack --analyze "/tmp/.nio_alloc_counter_tests_GRusAy/heaptrack.test_1000_autoReadGetAndSet.84341.gz"
```
Then run it a second time for the feature branch:
```
ubuntu@ip-172-31-25-161 /t/.nio_alloc_counter_tests_ARusXy> heaptrack .build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
heaptrack output will be written to "/tmp/.nio_alloc_counter_tests_GRusAy/heaptrack.test_1000_autoReadGetAndSet.84372.gz"
starting application, this might take some time...
test_1000_autoReadGetAndSet.remaining_allocations: 0
test_1000_autoReadGetAndSet.total_allocations: 0
test_1000_autoReadGetAndSet.total_allocated_bytes: 0
DEBUG: [["remaining_allocations": 0, "total_allocations": 0, "total_allocated_bytes": 0], ["total_allocated_bytes": 0, "total_allocations": 0, "remaining_allocations": 0], ["total_allocated_bytes": 0, "remaining_allocations": 0, "total_allocations": 0], ["total_allocations": 0, "total_allocated_bytes": 0, "remaining_allocations": 0], ["total_allocations": 0, "remaining_allocations": 0, "total_allocated_bytes": 0], ["remaining_allocations": 0, "total_allocations": 0, "total_allocated_bytes": 0], ["total_allocations": 0, "total_allocated_bytes": 0, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocated_bytes": 0, "total_allocations": 0], ["remaining_allocations": 0, "total_allocations": 0, "total_allocated_bytes": 0], ["remaining_allocations": 0, "total_allocated_bytes": 0, "total_allocations": 0]]
free(): invalid pointer
Aborted (core dumped)
heaptrack stats:
allocations: 673989
leaked allocations: 117
temporary allocations: 341011
Heaptrack finished! Now run the following to investigate the data:
heaptrack --analyze "/tmp/.nio_alloc_counter_tests_GRusAy/heaptrack.test_1000_autoReadGetAndSet.84372.gz"
ubuntu@ip-172-31-25-161 /t/.nio_alloc_counter_tests_GRusAy>
```
Here we could see that we had 673989 allocations in the feature branch version and 319347 in `main`, so clearly a regression.
Finally, we can analyze the output as a diff from these runs using `heaptrack_print`:
```
heaptrack_print -T -d heaptrack.test_1000_autoReadGetAndSet.84341.gz heaptrack.test_1000_autoReadGetAndSet.84372.gz | swift demangle
```
`-T` gives us the temporary allocations (as it in this case was not a leak, but a transient alloaction - if you have leaks remove `-T`).
The output can be quite long, but in this case as we look for transient allocations, scroll down to:
```
MOST TEMPORARY ALLOCATIONS
307740 temporary allocations of 290324 allocations in total (106.00%) from
swift_slowAlloc
in /home/ubuntu/bin/usr/lib/swift/linux/libswiftCore.so
43623 temporary allocations of 44553 allocations in total (97.91%) from:
swift_allocObject
in /home/ubuntu/bin/usr/lib/swift/linux/libswiftCore.so
NIO.ServerBootstrap.(bind0 in _C131C0126670CF68D8B594DDFAE0CE57)(makeServerChannel: (NIO.SelectableEventLoop, NIO.EventLoopGroup) throws -> NIO.ServerSocketChannel, _: (NIO.EventLoop, NIO.ServerSocketChannel) -> NIO.EventLoopFuture<()>) -> NIO.EventLoopFuture<NIO.Channel>
at /home/ubuntu/swiftnio/swift-nio/Sources/NIO/Bootstrap.swift:295
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
merged NIO.ServerBootstrap.bind(host: Swift.String, port: Swift.Int) -> NIO.EventLoopFuture<NIO.Channel>
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
NIO.ServerBootstrap.bind(host: Swift.String, port: Swift.Int) -> NIO.EventLoopFuture<NIO.Channel>
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
Test_test_1000_autoReadGetAndSet.run(identifier: Swift.String) -> ()
at /tmp/.nio_alloc_counter_tests_GRusAy/Sources/Test_test_1000_autoReadGetAndSet/file.swift:24
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
main
at Sources/bootstrap_test_1000_autoReadGetAndSet/main.c:18
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
22208 temporary allocations of 22276 allocations in total (99.69%) from:
swift_allocObject
in /home/ubuntu/bin/usr/lib/swift/linux/libswiftCore.so
generic specialization <Swift.UnsafeBufferPointer<Swift.Int8>> of Swift._copyCollectionToContiguousArray<A where A: Swift.Collection>(A) -> Swift.ContiguousArray<A.Element>
in /home/ubuntu/bin/usr/lib/swift/linux/libswiftCore.so
Swift.String.utf8CString.getter : Swift.ContiguousArray<Swift.Int8>
in /home/ubuntu/bin/usr/lib/swift/linux/libswiftCore.so
NIO.Uring.getEnvironmentVar(Swift.String) -> Swift.String?
at /home/ubuntu/swiftnio/swift-nio/Sources/NIO/LinuxUring.swift:291
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
NIO.Uring._debugPrint(@autoclosure () -> Swift.String) -> ()
at /home/ubuntu/swiftnio/swift-nio/Sources/NIO/LinuxUring.swift:297
...
22196 temporary allocations of 22276 allocations in total (99.64%) from:
```
And here we could fairly quickly see that the transient extra allocations was due to extra debug printing and querying of environment variables:
```
NIO.Uring.getEnvironmentVar(Swift.String) -> Swift.String?
at /home/ubuntu/swiftnio/swift-nio/Sources/NIO/LinuxUring.swift:291
in /tmp/.nio_alloc_counter_tests_GRusAy/.build/x86_64-unknown-linux-gnu/release/test_1000_autoReadGetAndSet
NIO.Uring._debugPrint(@autoclosure () -> Swift.String) -> ()
```
And this code will be removed before final integration of the feature branch, so the diff will go away.