Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[SR-9518] Swift doesn't seem to correctly deinit some objects (5.0 snapshots, release mode) #51970

Closed
weissi opened this issue Dec 14, 2018 · 3 comments
Closed

[SR-9518] Swift doesn't seem to correctly deinit some objects (5.0 snapshots, release mode) #51970

weissi opened this issue Dec 14, 2018 · 3 comments
Assignees
@eeckstein
Labels
bug A deviation from expected or documented behavior. Also: expected but undesirable behavior. compiler The Swift compiler in itself optimized only Flag: An issue whose reproduction requires optimized compilation

Comments

@weissi
Copy link
Member

weissi commented Dec 14, 2018

Previous ID SR-9518
Radar rdar://problem/46794455
Original Reporter @weissi
Type Bug
Status Resolved
Resolution Done

Attachment: Download

Additional Detail from JIRA
Votes 0
Component/s Compiler
Labels Bug, OptimizedOnly
Assignee @eeckstein
Priority Medium

md5: 6933683c4f7ddf0cbef9b51c845c5941

Issue Description:

Description

Our intregration tests started reporting leaks with Swift 5. They show 16 leaks per connection that is created which is odd because it never happened before. But still, why do I think this is a Swift bug and not a NIO bug:

  • only happens in release mode

  • MemoryGraphDebugger (see screenshot) shows the leaked objects but no incoming references

  • doesn't happen with all Swift 4.x versions

Repro

I attached a repro (tar.gz) which run in debug mode doesn't leak but it does leak in release mode. I tested with the Swift 5.0 dev snapshot from the 12th December:

$ jw-swift-latest swift --version
Apple Swift version 5.0-dev (LLVM f0eaafaa71, Clang f8aee5e310, Swift b490a2a83f)
Target: x86_64-apple-darwin18.2.0

happens on Mac & Linux.

instructions:

tar xf repro.tar.gz
cd repro
swift run -c release
# wait maybe 5 to 10s
# attach with Xcode and check the memory graph debugger

extra information

Here's the NIO PR that shows that the integration tests failed: apple/swift-nio#710

Here's the output of our allocation counter tests (with commentary)

19:04:12 1000_reqs_1_conn.remaining_allocations: 16
19:04:12 1000_reqs_1_conn.total_allocations: 38655
19:04:12 DEBUG: [["remaining_allocations": 16, "total_allocations": 38655], ["total_allocations": 38655, "remaining_allocations": 16], ["total_allocations": 38655, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 38655], ["remaining_allocations": 16, "total_allocations": 38655], ["remaining_allocations": 16, "total_allocations": 38655], ["total_allocations": 38655, "remaining_allocations": 16], ["total_allocations": 38655, "remaining_allocations": 16], ["total_allocations": 38655, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 38655]]

we ran the 'make 1000 HTTP/1.1 requests over 1 connection (keep-alive)' allocated 38655 times in total and after the end, 16 allocations were not free 'd. So probably 16 objects leaked. The repetitions are just because we re-run this 10 times.

19:04:12 1_reqs_1000_conn.remaining_allocations: 16000
19:04:12 1_reqs_1000_conn.total_allocations: 693000
19:04:12 DEBUG: [["remaining_allocations": 16000, "total_allocations": 693000], ["remaining_allocations": 16000, "total_allocations": 693000], ["remaining_allocations": 16000, "total_allocations": 693000], ["total_allocations": 693000, "remaining_allocations": 16000], ["total_allocations": 693000, "remaining_allocations": 16000], ["remaining_allocations": 16000, "total_allocations": 693000], ["total_allocations": 693000, "remaining_allocations": 16000], ["total_allocations": 693000, "remaining_allocations": 16000], ["remaining_allocations": 16000, "total_allocations": 693000], ["remaining_allocations": 16000, "total_allocations": 693000]]

we ran the 'make 1 HTTP/1.1 request per connection but do 1000 connections, one after the other'. In total we allocated 693000 things and 16000 of those didn't get free'd. That matches nicely with the 16 leaks above (1 connection) and now 16000 leaks (1000) connections.

Further allocation counter tests:

19:04:12 ping_pong_1000_reqs_1_conn.remaining_allocations: 16
19:04:12 ping_pong_1000_reqs_1_conn.total_allocations: 4511
19:04:12 DEBUG: [["remaining_allocations": 16, "total_allocations": 4511], ["total_allocations": 4511, "remaining_allocations": 16], ["total_allocations": 4511, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 4511], ["remaining_allocations": 16, "total_allocations": 4511], ["remaining_allocations": 16, "total_allocations": 4511], ["total_allocations": 4511, "remaining_allocations": 16], ["total_allocations": 4511, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 4511], ["remaining_allocations": 16, "total_allocations": 4511]]
19:04:12 bytebuffer_lots_of_rw.remaining_allocations: 0
19:04:12 bytebuffer_lots_of_rw.total_allocations: 3011
19:04:12 DEBUG: [["remaining_allocations": 0, "total_allocations": 3011], ["remaining_allocations": 0, "total_allocations": 3011], ["remaining_allocations": 0, "total_allocations": 3011], ["total_allocations": 3011, "remaining_allocations": 0], ["total_allocations": 3011, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 3011], ["remaining_allocations": 0, "total_allocations": 3011], ["total_allocations": 3011, "remaining_allocations": 0], ["total_allocations": 3011, "remaining_allocations": 0], ["total_allocations": 3011, "remaining_allocations": 0]]
19:04:12 future_lots_of_callbacks.remaining_allocations: 0
19:04:12 future_lots_of_callbacks.total_allocations: 99001
19:04:12 DEBUG: [["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001], ["total_allocations": 99001, "remaining_allocations": 0], ["total_allocations": 99001, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001], ["total_allocations": 99001, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001]]
19:04:12 ++ for test in 1000_reqs_1_conn 1_reqs_1000_conn ping_pong_1000_reqs_1_conn bytebuffer_lots_of_rw future_lots_of_callbacks
19:04:12 ++ cat /tmp/.swift-nio-http1-server-sh-tests_F9HU12/test.tmp_u3HDKT/output
19:04:12 1000_reqs_1_conn.remaining_allocations: 16
19:04:12 1000_reqs_1_conn.total_allocations: 38655
19:04:12 DEBUG: [["remaining_allocations": 16, "total_allocations": 38655], ["total_allocations": 38655, "remaining_allocations": 16], ["total_allocations": 38655, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 38655], ["remaining_allocations": 16, "total_allocations": 38655], ["remaining_allocations": 16, "total_allocations": 38655], ["total_allocations": 38655, "remaining_allocations": 16], ["total_allocations": 38655, "remaining_allocations": 16], ["total_allocations": 38655, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 38655]]
19:04:12 1_reqs_1000_conn.remaining_allocations: 16000
19:04:12 1_reqs_1000_conn.total_allocations: 693000
19:04:12 DEBUG: [["remaining_allocations": 16000, "total_allocations": 693000], ["remaining_allocations": 16000, "total_allocations": 693000], ["remaining_allocations": 16000, "total_allocations": 693000], ["total_allocations": 693000, "remaining_allocations": 16000], ["total_allocations": 693000, "remaining_allocations": 16000], ["remaining_allocations": 16000, "total_allocations": 693000], ["total_allocations": 693000, "remaining_allocations": 16000], ["total_allocations": 693000, "remaining_allocations": 16000], ["remaining_allocations": 16000, "total_allocations": 693000], ["remaining_allocations": 16000, "total_allocations": 693000]]
19:04:12 ping_pong_1000_reqs_1_conn.remaining_allocations: 16
19:04:12 ping_pong_1000_reqs_1_conn.total_allocations: 4511
19:04:12 DEBUG: [["remaining_allocations": 16, "total_allocations": 4511], ["total_allocations": 4511, "remaining_allocations": 16], ["total_allocations": 4511, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 4511], ["remaining_allocations": 16, "total_allocations": 4511], ["remaining_allocations": 16, "total_allocations": 4511], ["total_allocations": 4511, "remaining_allocations": 16], ["total_allocations": 4511, "remaining_allocations": 16], ["remaining_allocations": 16, "total_allocations": 4511], ["remaining_allocations": 16, "total_allocations": 4511]]
19:04:12 bytebuffer_lots_of_rw.remaining_allocations: 0
19:04:12 bytebuffer_lots_of_rw.total_allocations: 3011
19:04:12 DEBUG: [["remaining_allocations": 0, "total_allocations": 3011], ["remaining_allocations": 0, "total_allocations": 3011], ["remaining_allocations": 0, "total_allocations": 3011], ["total_allocations": 3011, "remaining_allocations": 0], ["total_allocations": 3011, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 3011], ["remaining_allocations": 0, "total_allocations": 3011], ["total_allocations": 3011, "remaining_allocations": 0], ["total_allocations": 3011, "remaining_allocations": 0], ["total_allocations": 3011, "remaining_allocations": 0]]
19:04:12 future_lots_of_callbacks.remaining_allocations: 0
19:04:12 future_lots_of_callbacks.total_allocations: 99001
19:04:12 DEBUG: [["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001], ["total_allocations": 99001, "remaining_allocations": 0], ["total_allocations": 99001, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001], ["total_allocations": 99001, "remaining_allocations": 0], ["remaining_allocations": 0, "total_allocations": 99001], ["remaining_allocations": 0, "total_allocations": 99001]]
@belkadan
Copy link
Contributor

cc @eeckstein

@eeckstein
Copy link
Member

It's a bug in SILCombine/ARCAnalysis

@eeckstein
Copy link
Member

Fixed on master: #21391
PR for 5.0: #21408

@swift-ci swift-ci transferred this issue from apple/swift-issues Apr 25, 2022
This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@eeckstein eeckstein

Labels
bug A deviation from expected or documented behavior. Also: expected but undesirable behavior. compiler The Swift compiler in itself optimized only Flag: An issue whose reproduction requires optimized compilation
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@weissi @belkadan @eeckstein