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

Update backpressure implementation with runtime configurable threshold #4151

Open
wants to merge 7 commits into
base: main
Choose a base branch
from

Conversation

dipinhora
Copy link
Contributor

@dipinhora dipinhora commented Jun 22, 2022

Prior to this commit, the backpressure implementation would
unschedule muted actors immediately after they sent a single
message to a muted/overloaded/under pressure actor. While this
works reasonably well, it does have some rough edges as noted
in #3382 and
#2980.

This commit updates the backpressure implementation that can
have its threshold for when to unschedule an actor sending
to muted/overloaded/under pressure actors be dynamically
controlled via a runtime cli argument. It does this by
separating an actor being muted from when an actor is
unscheduled where an actor is still muted immediately
upon sending a message to a muted/overloaded/under pressure
actor but the threshold controls when an actor is
unscheduled after it has been muted resulting in a more
gradual backpressure system. This threshold based
backpressure should result in less stalls and more overall
forward progress due to allowing muted actors to make some
slow progress prior to being uncheduled.

The updated backpressure logic is as follows (at a high level):

  • If sending a message to a muted/overloaded/under pressure actor,
    note that the sending actor should mute.
    • At the end of the behavior, mark the actor as muted if it
      is not already muted and save the receiver actor info.
    • At the end of the behavior, check to see if the actor is over
      the threshold.
      • If yes, unschedule actor and mark it as muted and unscheduled
        and finally add the sender and all muters to the scheduler
        mutemap (as used to happen previously after 1 message)
      • If no, stop processing messages but don't unschedule the actor
  • When an actor is no longer overloaded or under pressure, it will
    tell the schedulers to unmute all senders that were muted and
    unscheduled as a result of sending messages to it
    (same as previously)
  • When an actor runs it checks if it still needs to stay muted or not
    and if not, it tells the schedulers to unmute all senders that were
    muted and unscheduled as a result of sending messages to it
  • The actor also optimistically unmutes itself it successfully
    processes a full batch or all messages in its queue and tells the
    schedulers to unmute all senders that were muted and unscheduled
    as a result of sending messages to it

The updated logic is functionally equivalent to the old backpressure
implentation when the threshold is 1 message.

There is now a new command line argument to control the threshold
for throttling/muting called --ponymsgstilmute. This option is
specifically added for power users who want to have more control
over how the runtime handles backpressure. Using a value of 1
for --ponymsgstilmute will result in actors getting muted after
sending a single message to a muted/overloaded/under pressure
actor and be functionally equivalent to the previous backpressure
implementation that did not employ gradual throttling. The
threshold defaults to 10.

@ponylang-main ponylang-main added the discuss during sync Should be discussed during an upcoming sync label Jun 22, 2022
@dipinhora
Copy link
Contributor Author

NOTE: i've only done some limited testing and everything seems to work correctly (i.e. no deadlocks) almost all of the time (i have one last edge case bug that i'm still tracking down) but more extensive testing is required to confirm that i didn't miss something. Additionally, i have not run any performance tests as i don't really have a good environment to run those in. Aside from that, this is ready for folks to give some feedback on as i don't expect things to change drastically to resolve that last issue i'm tracking down.

@SeanTAllen
Copy link
Member

I'm probably not going to have a chance to perf test this for a couple weeks. Sorry for the slow pace.

@dipinhora dipinhora changed the title New backpressure implementation with runtime configurable threshold Update backpressure implementation with runtime configurable threshold Jun 26, 2022
@SeanTAllen
Copy link
Member

@dipinhora when you have time, can you run the overload program with the existing implementation and give an idea of where memory generally stabilizes across several local runs and then do the same with the new implementation with a few different settings including the one that should mimic the current implementation?

I would do it but I'm already not going to have a chance to perf test unless the weekend after the 4th.

@dipinhora
Copy link
Contributor Author

@SeanTAllen no problem... the latest incarnation of this that i just force pushed should have very similar performance characteristics as the current backpressure logic since it reuses almost all of it.

@SeanTAllen
Copy link
Member

@dipinhora can you give me different settings that you think would be important to use across however many different variations I test?

@dipinhora dipinhora marked this pull request as ready for review June 26, 2022 00:16
@dipinhora
Copy link
Contributor Author

Also, this PR not longer a draft and is ready for a more thorough review.

@dipinhora
Copy link
Contributor Author

dipinhora commented Jun 26, 2022

@SeanTAllen i did the following to confirm things are working as expected:

  • Should match current backpressure behavior: /usr/bin/time -v ./fan-in --ponymsgstilmute 1
  • Should work better than current backpressure/use more memory: /usr/bin/time -v ./fan-in --ponymsgstilmute 2
  • Should use even more memory: /usr/bin/time -v ./fan-in --ponymsgstilmute <5 or higher>

The behavior with --ponymsgstilmute 1 seemed to match the current backpressure implementation almost exactly as was expected. i didn't pay much attention to the number of messages because my development/testing environment is a VM on a busy laptop with cpu scaling/throttling enabled but they seemed roughly comparable to the current backpressure implementation.

i don't really have explicit suggestions in terms of number of variations to test but i would recommend using --ponymsgstilmute 1 for performance comparison purposes between this and the current implementation (of whichever apps; i.e. fan-in, overload, message-ubench, etc)..

@dipinhora
Copy link
Contributor Author

dipinhora commented Jun 26, 2022

@dipinhora when you have time, can you run the overload program with the existing implementation and give an idea of where memory generally stabilizes across several local runs and then do the same with the new implementation with a few different settings including the one that should mimic the current implementation?

Yes, i'll run the overload/fan-in/message-bench/etc in a few different ways (i've already done so with fan-in and memory usage matches when it should and is larger when given the appropriate arguments) and report back.. (but they won't be useful for performance, only memory usage)..

@dipinhora
Copy link
Contributor Author

dipinhora commented Jun 26, 2022

fan-in comparison between main and this PR (these were all debug builds). Reminder: my development/testing environment is a VM on a busy laptop with cpu scaling/throttling enabled and these runs aren't useful for performance comparisons, only memory usage.

fan-in-main run:

me@win:~/dhp$ /usr/bin/time -v ./fan-in-main
# senders 100, analyzers 1000, analyzer-interval 100, analyzer-report-count 10, receiver-workload 10000
time,run-ns,rate
1656199912731039500,9999848100,6308143
1656199922729502100,9998462600,4916895
1656199932728995000,9999492900,4724176
1656199942728633100,9999638100,125
1656199952727171800,9998538700,4281986
1656199962726684100,9999512300,3790925
1656199972726439700,9999755600,71
1656199982724946000,9998506300,3464567
1656199992724500000,9999554000,3663327
1656200002723330200,9998830200,69
Done with message sending... Waiting for Receiver to work through its backlog...
        Command being timed: "./fan-in-main"
        User time (seconds): 213.07
        System time (seconds): 0.78
        Percent of CPU this job got: 192%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:51.28
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 18716
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 975
        Voluntary context switches: 320375
        Involuntary context switches: 630
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

fan-in PR run to match main behavior with --ponymsgstilmute 1:

me@win:~/dhp$ /usr/bin/time -v ./fan-in --ponymsgstilmute 1
# senders 100, analyzers 1000, analyzer-interval 100, analyzer-report-count 10, receiver-workload 10000
time,run-ns,rate
Tick fired: 1
1656199792165770400,9999166300,7118022
Tick fired: 2
1656199802164313000,9998542600,4444114
Tick fired: 3
1656199812164063300,9999750300,3447193
Tick fired: 4
1656199822162805600,9998742300,100
Tick fired: 5
1656199832162547600,9999742000,4052361
Tick fired: 6
1656199842161064400,9998516800,4266027
Tick fired: 7
1656199852160812000,9999747600,93
Tick fired: 8
1656199862160513800,9999701800,4004184
Tick fired: 9
1656199872159080700,9998566900,3980778
Tick fired: 10
1656199882158816700,9999736000,132
Done with message sending... Waiting for Receiver to work through its backlog...
        Command being timed: "./fan-in --ponymsgstilmute 1"
        User time (seconds): 210.22
        System time (seconds): 0.98
        Percent of CPU this job got: 189%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:51.29
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 21588
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 212
        Voluntary context switches: 326754
        Involuntary context switches: 640
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

fan-in PR run with --ponymsgstilmute 2:

me@win:~/dhp$ /usr/bin/time -v ./fan-in --ponymsgstilmute 2
# senders 100, analyzers 1000, analyzer-interval 100, analyzer-report-count 10, receiver-workload 10000
time,run-ns,rate
Tick fired: 1
1656200057874540900,9998712300,5902318
Tick fired: 2
1656200067874138500,9999597600,4951389
Tick fired: 3
1656200077872635400,9998496900,4773326
Tick fired: 4
1656200087872247800,9999612400,5045490
Tick fired: 5
1656200097871851400,9999603600,4424406
Tick fired: 6
1656200107870354600,9998503200,4331224
Tick fired: 7
1656200117869953900,9999599300,4186002
Tick fired: 8
1656200127869528700,9999574800,4328545
Tick fired: 9
1656200137868081100,9998552400,4167887
Tick fired: 10
1656200147867776900,9999695800,3802718
Done with message sending... Waiting for Receiver to work through its backlog...
        Command being timed: "./fan-in --ponymsgstilmute 2"
        User time (seconds): 311.10
        System time (seconds): 0.25
        Percent of CPU this job got: 279%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:51.35
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 18840
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1006
        Voluntary context switches: 83241
        Involuntary context switches: 53
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

fan-in PR run with --ponymsgstilmute 5:

me@win:~/dhp$ /usr/bin/time -v ./fan-in --ponymsgstilmute 5
# senders 100, analyzers 1000, analyzer-interval 100, analyzer-report-count 10, receiver-workload 10000
time,run-ns,rate
Tick fired: 1
1656200182880736800,9998567600,4674834
Tick fired: 2
Tick fired: 3
Tick fired: 4
1656200192880277200,9999540400,4435324
Tick fired: 5
1656200202878815200,9998538000,4484246
Tick fired: 6
Tick fired: 7
Tick fired: 8
1656200212878397000,9999581800,4355203
Tick fired: 9
Tick fired: 10
1656200222877943600,9999546600,3354678
1656200232876498000,9998554400,4176515
1656200242876097000,9999599000,4149320
1656200252874703100,9998606100,3891656
1656200262874299700,9999596600,4085014
1656200272873905900,9999606200,3909715
Done with message sending... Waiting for Receiver to work through its backlog...
        Command being timed: "./fan-in --ponymsgstilmute 5"
        User time (seconds): 312.96
        System time (seconds): 0.33
        Percent of CPU this job got: 278%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:52.52
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 187216
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1749
        Voluntary context switches: 77868
        Involuntary context switches: 986
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

fan-in PR run with --ponymsgstilmute 10 (same as default):

me@win:~/dhp$ /usr/bin/time -v ./fan-in --ponymsgstilmute 10
# senders 100, analyzers 1000, analyzer-interval 100, analyzer-report-count 10, receiver-workload 10000
time,run-ns,rate
Tick fired: 1
1656200339568694100,9999356300,5656872
Tick fired: 2
Tick fired: 3
1656200349567245500,9998551400,3343434
Tick fired: 4
Tick fired: 5
Tick fired: 6
1656200359566817700,9999572200,3441709
1656200369566381200,9999563500,3273078
1656200379564918500,9998537300,3305244
1656200390060253200,10495334700,3183157
Tick fired: 7
Tick fired: 8
1656200399563133100,9502879900,3315086
1656200409562710700,9999577600,3295596
Tick fired: 9
Tick fired: 10
1656200419562294800,9999584100,3303666
1656200429560879400,9998584600,3400222
Done with message sending... Waiting for Receiver to work through its backlog...
        Command being timed: "./fan-in --ponymsgstilmute 10"
        User time (seconds): 311.38
        System time (seconds): 0.32
        Percent of CPU this job got: 278%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:51.72
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 89396
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1273
        Voluntary context switches: 80984
        Involuntary context switches: 586
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

@dipinhora
Copy link
Contributor Author

overload comparison between main and this PR (these were all debug builds). Reminder: my development/testing environment is a VM on a busy laptop with cpu scaling/throttling enabled and these runs aren't useful for performance comparisons, only memory usage.

overload-main run:

me@win:~/dhp$ /usr/bin/time -v ./overload-main
Starting 10000 senders.
Single receiver started.
50000000 messages received in 9766125700 nanos.
100000000 messages received in 10966257000 nanos.
150000000 messages received in 10838438000 nanos.
200000000 messages received in 10781727800 nanos.
250000000 messages received in 12068008600 nanos.
300000000 messages received in 10506856100 nanos.
350000000 messages received in 10554087000 nanos.
400000000 messages received in 10465686300 nanos.
450000000 messages received in 11194175800 nanos.
500000000 messages received in 11191582300 nanos.
Command terminated by signal 2
        Command being timed: "./overload-main"
        User time (seconds): 436.80
        System time (seconds): 0.00
        Percent of CPU this job got: 399%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:49.21
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 28600
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1008
        Voluntary context switches: 12
        Involuntary context switches: 842
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

overload PR run to match main behavior with --ponymsgstilmute 1:

me@win:~/dhp$ /usr/bin/time -v ./overload --ponymsgstilmute 1
Starting 10000 senders.
Single receiver started.
50000000 messages received in 7960315700 nanos.
100000000 messages received in 11358310500 nanos.
150000000 messages received in 10601384100 nanos.
200000000 messages received in 10825084900 nanos.
250000000 messages received in 10938268400 nanos.
300000000 messages received in 11621341700 nanos.
350000000 messages received in 11029614300 nanos.
400000000 messages received in 10945448400 nanos.
450000000 messages received in 10977005400 nanos.
500000000 messages received in 11005754900 nanos.
Command terminated by signal 2
        Command being timed: "./overload --ponymsgstilmute 1"
        User time (seconds): 433.32
        System time (seconds): 0.00
        Percent of CPU this job got: 399%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:48.33
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 32752
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 514
        Voluntary context switches: 14
        Involuntary context switches: 70
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

overload PR run with --ponymsgstilmute 2:

me@win:~/dhp$ /usr/bin/time -v ./overload --ponymsgstilmute 2
Starting 10000 senders.
Single receiver started.
50000000 messages received in 8505359100 nanos.
100000000 messages received in 13745801500 nanos.
150000000 messages received in 11345613600 nanos.
200000000 messages received in 11351674800 nanos.
250000000 messages received in 11348832000 nanos.
300000000 messages received in 11238215000 nanos.
350000000 messages received in 11299065400 nanos.
400000000 messages received in 11342703000 nanos.
450000000 messages received in 11374541700 nanos.
500000000 messages received in 11360390400 nanos.
Command terminated by signal 2
        Command being timed: "./overload --ponymsgstilmute 2"
        User time (seconds): 455.88
        System time (seconds): 0.01
        Percent of CPU this job got: 399%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:53.97
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 28276
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1476
        Voluntary context switches: 10
        Involuntary context switches: 57
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

overload PR run with --ponymsgstilmute 5:

me@win:~/dhp$ /usr/bin/time -v ./overload --ponymsgstilmute 5
Starting 10000 senders.
Single receiver started.
50000000 messages received in 19813447500 nanos.
100000000 messages received in 20200187500 nanos.
150000000 messages received in 20290296500 nanos.
200000000 messages received in 20006596800 nanos.
250000000 messages received in 19952067700 nanos.
300000000 messages received in 19849536200 nanos.
350000000 messages received in 20231104500 nanos.
400000000 messages received in 19920290700 nanos.
450000000 messages received in 20009192400 nanos.
500000000 messages received in 20245867300 nanos.
Command terminated by signal 2
        Command being timed: "./overload --ponymsgstilmute 5"
        User time (seconds): 805.82
        System time (seconds): 0.02
        Percent of CPU this job got: 399%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 3:21.47
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 33216
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1129
        Voluntary context switches: 123
        Involuntary context switches: 85
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

overload PR run with --ponymsgstilmute 10 (same as default):

me@win:~/dhp$ /usr/bin/time -v ./overload --ponymsgstilmute 10
Starting 10000 senders.
Single receiver started.
50000000 messages received in 14823565800 nanos.
100000000 messages received in 20049751100 nanos.
150000000 messages received in 20391243300 nanos.
200000000 messages received in 20315760800 nanos.
250000000 messages received in 20085073000 nanos.
300000000 messages received in 20091963700 nanos.
350000000 messages received in 20104460800 nanos.
400000000 messages received in 20727572700 nanos.
450000000 messages received in 20429534000 nanos.
500000000 messages received in 20089990000 nanos.
Command terminated by signal 2
        Command being timed: "./overload --ponymsgstilmute 10"
        User time (seconds): 793.19
        System time (seconds): 0.03
        Percent of CPU this job got: 399%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 3:18.30
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 31864
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1313
        Voluntary context switches: 18
        Involuntary context switches: 430
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

@dipinhora
Copy link
Contributor Author

@SeanTAllen i've added comparison runs for overload and fan-in.. They both behave roughly as expected. fan-in seems to be a better representation of how the larger --ponymsgstilmute values lead to additional queueing and memory use by the program.

@SeanTAllen
Copy link
Member

I can see this is going to take a while to review.

@SeanTAllen
Copy link
Member

this needs a rebase btw

@SeanTAllen
Copy link
Member

@dipinhora do you think this is a PR where we could find time next week to go over synchronously?

@dipinhora
Copy link
Contributor Author

rebased onto latest main and review comments addressed..

@dipinhora do you think this is a PR where we could find time next week to go over synchronously?

@SeanTAllen i can usually make time on most weekday evenings after 6 pm EST if that works for you (and also between 8 am EST and 9:30 am EST if you prefer morning time).. Weekends are sometimes a bit more flexible if that's better for you. Let me know what day/time would work best for you.

@dipinhora
Copy link
Contributor Author

i don't believe the CI failures are related to the changes in this PR. i'm going to retry them to see if they pass.

arm64 darwin failure:

**** FAILED: property_runner/async/complete_multi_fail_action

x86-64 windows failure:

**** FAILED: process/STDIN-WriteBuf

@dipinhora
Copy link
Contributor Author

Not sure what's causing the windows test hanging issue but i don't believe it's related to changes in this PR (the same windows test hanging issue occurred in #4144 but that resolved itself automagically upon a non-code commit to the release notes).

i've tried setting up a windows environment but haven't been able to reproduce the issue.

any ideas?

@SeanTAllen
Copy link
Member

Windows tests hanging would be new. What are you seeing in the CI specifically?

@dipinhora
Copy link
Contributor Author

dipinhora commented Jul 11, 2022

The windows CI issues are showing the following symptoms:

  • Sometimes **** FAILED: process/STDIN-WriteBuf fails and other times it passes
  • debug_test fails with a Timed out! at the end after running for almost 2 hours

The same issue occurred on this PR (https://github.com/ponylang/ponyc/runs/7102036651) and on the enhance runtime stats tracking PR (https://github.com/ponylang/ponyc/runs/7267743083) but the enhance runtime stats tracking PR passed on it's own after i pushed a commit to update the release notes (this is why i don't think this PR is the root cause of this hanging issue).

Also, i set up a windows dev environment and i am unable to reproduce this hanging/time ouot issue.

@SeanTAllen
Copy link
Member

I apologize for work being very busy right now and not having had time to get to this.

@SeanTAllen
Copy link
Member

@dipinhora

debug_test fails with a Timed out! at the end after running for almost 2 hours

this appears to be related to something going haywire with the WriteBuf test, no?

@kulibali is this a new one? I don't remember seeing it any time recently and if I did in the past, I don't remember.

Sometimes **** FAILED: process/STDIN-WriteBuf fails and other times it passes

@dipinhora
Copy link
Contributor Author

@dipinhora

debug_test fails with a Timed out! at the end after running for almost 2 hours

this appears to be related to something going haywire with the WriteBuf test, no?

Not always, but yes, the WriteBuf test also tends to time out/fail often when the hang occurs.

@dipinhora
Copy link
Contributor Author

I apologize for work being very busy right now and not having had time to get to this.

It happens. Ping me whenever you have time.

@SeanTAllen
Copy link
Member

At @dipinhora so... I'm looking at what is going on with this test. And it is backpressure adjacent. It calls "backpressure.apply" when the pipe it is writing to isn't available to take all the data. See:

https://github.com/ponylang/ponyc/blob/main/packages/process/process_monitor.pony#L422

This is a very very weird looking one.

It looks like this has been failing since at least a week ago, that is the oldest one I can see in the history on CirrusCI.

@dipinhora
Copy link
Contributor Author

And it is backpressure adjacent. It calls "backpressure.apply" when the pipe it is writing to isn't available to take all the data.

Yes, i saw that but the same thing works fine on all the other OS's and on my local windows environment.

Yes, the first failure was from two weeks ago when the latest commit was pushed (i retried a few time since then).

Very annoying that it can't be reproduced locally.

@SeanTAllen
Copy link
Member

So I just did a PR against master and the Windows stuff passed just fine. It makes me think the issues you are hitting might be related to the changes. Somehow.

@jemc jemc removed the discuss during sync Should be discussed during an upcoming sync label Jul 19, 2022
Prior to this commit, the backpressure implementation would
unschedule muted actors immediately after they sent a single
message to a muted/overloaded/under pressure actor. While this
works reasonably well, it does have some rough edges as noted
in ponylang#3382 and
ponylang#2980.

This commit updates the backpressure implementation that can
have its threshold for when to unschedule an actor sending
to muted/overloaded/under pressure actors be dynamically
controlled via a runtime cli argument. It does this by
separating an actor being muted from when an actor is
unscheduled where an actor is still muted immediately
upon sending a message to a muted/overloaded/under pressure
actor but the threshold controls when an actor is
unscheduled after it has been muted resulting in a more
gradual backpressure system. This threshold based
backpressure should result in less stalls and more overall
forward progress due to allowing muted actors to make some
slow progress prior to being uncheduled.

The updated backpressure logic is as follows (at a high level):

* If sending a message to a muted/overloaded/under pressure actor,
  note that the sending actor should mute.
  * At the end of the behavior, mark the actor as `muted` if it
    is not already `muted` and save the receiver actor info.
  * At the end of the behavior, check to see if the actor is over
    the threshold.
    * If yes, unschedule actor and mark it as `muted and unscheduled`
      and finally add the sender and all muters to the scheduler
      mutemap (as used to happen previously after 1 message)
    * If no, stop processing messages but don't unschedule the actor
* When an actor is no longer overloaded or under pressure, it will
  tell the schedulers to unmute all senders that were muted and
  unscheduled as a result of sending messages to it
  (same as previously)
* When an actor runs it checks if it still needs to stay `muted` or not
  and if not, it tells the schedulers to unmute all senders that were
  muted and unscheduled as a result of sending messages to it
* The actor also optimistically unmutes itself it successfully
  processes a full batch or all messages in its queue and tells the
  schedulers to unmute all senders that were muted and unscheduled
  as a result of sending messages to it

The updated logic is functionally equivalent to the old backpressure
implentation when the threshold is `1` message.

There is now a new command line argument to control the threshold
for throttling/muting called `--ponymsgstilmute`. This option is
specifically added for power users who want to have more control
over how the runtime handles backpressure. Using a value of `1`
for `--ponymsgstilmute` will result in actors getting muted after
sending a single message to a muted/overloaded/under pressure
actor and be functionally equivalent to the previous backpressure
implementation that did not employ gradual throttling. The
threshold defaults to `10`.
Prior to this commit, an actor with no pending messages being
unmuted could end up running concurrently on two scheduler
threads due to a race condition. The specific issue is that we
`unmute the actor` and then we `schedule the actor`. It is
entirely possible that the unmuted actor could get scheduled
on a different scheduler thread if another actor sent it a
message at the same time as we schedule it to run on the
current scheduler thread.

This commit changes the logic to check whether the actor
has any pending messages or not prior to unmuting it and
will only reschedule the actor if the actor actually had
pending messages to process already waiting in its queue.
…ntly"

This reverts commit dbfbd9a.

Reverting this because it's an incomplete fix and a proper fix will require
larger changes. Will revisit later.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants