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.

Sign up for GitHub

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

[not for merge] tidying threads and file descriptors at shutdown #3397

Draft
wants to merge 7 commits into
base: master
Choose a base branch
from
Draft

[not for merge] tidying threads and file descriptors at shutdown #3397

wants to merge 7 commits into from
+78 −19

Conversation

benclifford
Copy link
Collaborator

this is a patch stack in my dev environment where i have been pushing on cleanup of threads and file descriptors at shutdown, with the eventual goal of having pytest fixtures assert that only the main thread is running and the same number of file descriptors are open at the start and the end. I've been merging work from this already in small pieces and will continue to merge small tidyups from it.

There is at least one large part which needs some thought and discussion, which is how to shut down the htex queue processing thread - the engine of almost everything in htex that doesn't happen immediately on user task submission.

@benclifford benclifford marked this pull request as draft April 25, 2024 07:28
@benclifford benclifford force-pushed the benc-stdstreams-bugs branch 4 times, most recently from ef0f2bf to ea3f8f7 Compare April 29, 2024 12:26
@benclifford benclifford mentioned this pull request Jul 1, 2024
Merged
benclifford added a commit that referenced this pull request Jul 2, 2024
@benclifford
Join on stopped thread at end of LocalProvider+ssh test
1c1e47f 
This stops that thread being left still running over the end of the
test - which is needed in work in PR #3397 to ensure that no threads
are left running at the end of a test.

If that shutdown hangs, this test will now hang rather than leave the
thread behind.

Along with PR #3504, this eliminates any threads left behind after
parsl/tests/test_providers/test_local_provider.py
@benclifford benclifford mentioned this pull request Jul 2, 2024
Merged
benclifford added a commit that referenced this pull request Jul 3, 2024
@benclifford
Join on stopped thread at end of LocalProvider+ssh test (#3505)
2cc3ec5 
This stops that thread being left still running over the end of the
test - which is needed in work in PR #3397 to ensure that no threads
are left running at the end of a test.

If that shutdown hangs, this test will now hang rather than leave the
thread behind.

Along with PR #3504, this eliminates any threads left behind after
parsl/tests/test_providers/test_local_provider.py
@benclifford benclifford mentioned this pull request Jul 10, 2024
Closed
benclifford added a commit that referenced this pull request Aug 8, 2024
@benclifford
Close processes in Work Queue and Task Vine shutdown
1b0b933 
This releases 2 file descriptors with work queue (from 21 to 19 at the end
of CI Work Queue test) and 4 file descriptors with Task Vine (from 19 to 15
at the end of CI Task Vine test)

This is part of work being merged from draft PR #3397 to shut down components
more cleanly, rather than relying on process exit.
@benclifford benclifford mentioned this pull request Aug 8, 2024
Merged
benclifford added a commit that referenced this pull request Aug 8, 2024
@benclifford
Close processes in Work Queue and Task Vine shutdown (#3576)
114e701 
This releases 2 file descriptors with work queue (from 21 to 19 at the end
of CI Work Queue test) and 4 file descriptors with Task Vine (from 19 to 15
at the end of CI Task Vine test)

This is part of work being merged from draft PR #3397 to shut down components
more cleanly, rather than relying on process exit.
@benclifford benclifford force-pushed the benc-stdstreams-bugs branch 2 times, most recently from e2b0448 to 96f1e63 Compare August 16, 2024 13:01
@benclifford benclifford mentioned this pull request Oct 19, 2024
Merged
benclifford added a commit that referenced this pull request Oct 19, 2024
@benclifford
Reduce load on drain integration test to reduce race-condition failur…
973ee48 
…es (#3640)

This PR reduces the load places on the interchange and on the whole test environment caused by repeatedly querying the interchange for connected managers. It does this by increasing the period between such requests, from the default, every 20ms, to every 100ms.

In the last few days, test_drain.py began failing often. I have seen it occasionally fail before. This was initially a problem in PR #3639 which is unrelated, but I recreated the problem in CI against master as of #3627.

I investigated and found this behaviour causing the failure:

* test_drain configures the drain period to be 1 second
* startup of a worker pool was taking more than 1 second
* the worker pool enters drain state, drains and terminates immediately on being fully started up.
* test_py fails its assumption that there is a worker pool to inspect after waiting for there to be worker pool to inspect. This is the race condition: the assertion at line 57 is true but line 59 returns an empty managers list.

```
57    try_assert(lambda: len(htex.connected_managers()) == 1, check_period_ms=CONNECTED_MANAGERS_POLL_MS)
58
59    managers = htex.connected_managers()
60    assert managers[0]['active'], "The manager should be active"
```

Looking at the CI logs for a failing case, I saw direct evidence that the worker pool takes more than 1 second to start up in `manager.log`:

```
2024-10-18 10:31:16.007 parsl:914 29414 MainThread [INFO]  Python version: 3.12.7 (main, Oct  1 2024, 15:17:50) [GCC 9.4.0]
[...]
2024-10-18 10:31:16.008 parsl:151 29414 MainThread [INFO]  Manager initializing
[this is where the worker start time for drain purposes is measured]
[...]
2024-10-18 10:31:16.011 parsl:183 29414 MainThread [INFO]  Manager connected to interchange
2024-10-18 10:31:17.058 parsl:243 29414 MainThread [INFO]  Will request drain at 1729247477.0087547
[...]
2024-10-18 10:31:17.073 parsl:336 29414 Task-Puller [DEBUG]  ready workers: 0, pending tasks: 0
```

There's more than a second delay between "... connected to interchange" and the subsequent message "Will request drain". There's not a huge amount of stuff happening between these lines but there are things like multiprocessing initialization which starts a new process.

It looks like this bit of code is slow even in the successful case: rerunning until success, I see this timing in CI:

```
2024-10-18 12:11:17.475 parsl:183 23062 MainThread [INFO]  Manager connected to interchange
2024-10-18 12:11:18.181 parsl:243 23062 MainThread [INFO]  Will request drain at 1729253478.4731379
```

which is still a large fraction of a second (but sufficiently less than a second for the test to pass).

I haven't investigated what is taking that time. I haven't investigated if I also see that on my laptop.

I hypothesised that a lot of these test failures come from the test environment being quite loaded. I'm especially suspicious of using `try_assert` with its default timings which are very tight (20ms) - the connected managers RPC here would be expected to run much less frequently, more like every 5 seconds in regular Parsl use.

So I lengthed the period of the try_asserts in this test, to try to reduce load caused there.

That makes the test pass repeatedly again.

Things not investigated/debugged:

* why this is taking >0.5 second even in the successful case - it's possible that this is a reasonable startup time and so the test might be lengthened by a few seconds
* how to do a test without being timing reliant - draining is, by its very nature, reliant on the passage of "real time". For example, you might mock (at the libc level if not at the Python level) system time.
* what other loads are present on the system - one of the points of slowly-ongoing PR #3397 shutdown tidyup is to reduce thread load left behind by earlier tests
@benclifford benclifford removed the demo label Nov 29, 2024
@benclifford
log fd counts
9d3d3cc
@benclifford
tmp: log threads
0ac0775
@benclifford
hack tv diskspace for hang
b857453
@benclifford
Prototype htex result queue shutdown
0964f5a 
Before this PR, this thread stays running forever, until it is terminated
by Python process exit.

After this PR, this thread polls an flag once per second, then properly
closes the ZMQ socket that it is using.

pytest parsl/tests/test_monitoring/ --config local
Before this PR, at end of test: 32 threads, 451 fds open.

After this PR, at end of test: 1 thread, 48 fds open.
@benclifford
assert on number of threads left running after each test in config lo…
a839e03 
…cal test
@benclifford
radical mpi test leaves lots of threads:
72c8dd5 
parsl/tests/test_radical/test_mpi_funcs.py

...


            logger.error(f"BENC: end open fds: {end_fds} (vs start {start_fds}")
            logger.error(f"BENC: end threads: {threading.active_count()}")
    
>           assert threading.active_count() == 1, "test left threads running: " + repr(threading.enumerate())
E           AssertionError: test left threads running: [<_MainThread(MainThread, started 140532448974656)>, <Thread(Thread-18 (
_work), started daemon 140531866793664)>, <Thread(Thread-19 (_run_proxy), started daemon 140531858400960)>, <Thread(Thread-20 (
_monitor), started daemon 140531850008256)>, <Thread(Thread-21 (_work), started daemon 140531841615552)>, <Thread(Thread-23 (_w
atch), started daemon 140531229243072)>, <Thread(Thread-24 (_listener), started daemon 140531220850368)>, <Thread(Thread-25 (_l
istener), started daemon 140530985985728)>, <Thread(Thread-26 (_listener), started daemon 140530977593024)>, <Thread(Thread-27 
(_listener), started daemon 140530969200320)>, <Thread(Thread-28 (_listener), started daemon 140530960807616)>, <Thread(Thread-
29 (_listener), started daemon 140530952414912)>, <Thread(Thread-31 (_listener), started daemon 140530390398656)>, <Thread(Thre
ad-32 (_listener), started daemon 140530365220544)>, <Thread(Thread-33 (_listener), started daemon 140530113570496)>, <Thread(T
hread-35 (_listener), started daemon 140530096785088)>, <Thread(Thread-36 (_listener), started daemon 140530071606976)>, <Threa
d(Thread-38 (_listener), started daemon 140529627023040)>, <Thread(Thread-39 (_listener), started daemon 140529618630336)>, <Th
read(Thread-40 (_bulk_collector), started daemon 140529610237632)>]
E           assert 20 == 1
E            +  where 20 = <function active_count at 0x7fd041fcfec0>()
E            +    where <function active_count at 0x7fd041fcfec0> = threading.active_count
@benclifford
count fds
254d8ba
@benclifford benclifford mentioned this pull request Nov 29, 2024
Open
benclifford added a commit that referenced this pull request Nov 29, 2024
@benclifford
Make result queue poll for shutdown, and tidy up at shutdown
9ea4e14 
This poll happens at the configured htex poll period, which defaults to
10ms.

Under heavy result load, this shoudn't result in much additional load:
the poll loop will already be looping a lot to process the results.

Under lower result load, there is a slight observable increase in CPU
usage: a 30second sleep task shows this before this PR:

before:
real    0m37.451s
user    0m2.160s
sys     0m0.376s

run 2, user 2.160s
run 3, user 2.116s

and this after this PR:

real    0m37.473s
user    0m2.400s
sys     0m0.557s

Run 2, 2.457s
Run 3, 2.452s

At shutdown, the ZMQ socket for incoming results is closed.

This reduces both the number of threads and number of file descriptors
left behind by the `--config local` tests. For example:

$ pytest parsl/tests/test_monitoring/ --config local

Before this PR, at end of test: 32 threads, 451 fds open.

After this PR, at end of test: 1 thread, 48 fds open.

This is part of PR #3397 shutdown tidyup.
@benclifford benclifford mentioned this pull request Nov 29, 2024
Merged
github-merge-queue bot pushed a commit that referenced this pull request Dec 2, 2024
@benclifford
Make result queue poll for shutdown, and tidy up at shutdown (#3709)
7622caa 
This poll happens at the configured htex poll period, which defaults to
10ms.

Under heavy result load, this shoudn't result in much additional load:
the poll loop will already be looping a lot to process the results.

Under lower result load, there is a slight observable increase in CPU
usage: a 30second sleep task shows this before this PR:

before:
real    0m37.451s
user    0m2.160s
sys     0m0.376s

run 2, user 2.160s
run 3, user 2.116s

and this after this PR:

real    0m37.473s
user    0m2.400s
sys     0m0.557s

Run 2, 2.457s
Run 3, 2.452s

At shutdown, the ZMQ socket for incoming results is closed.

This reduces both the number of threads and number of file descriptors
left behind by the `--config local` tests. For example:

$ pytest parsl/tests/test_monitoring/ --config local

Before this PR, at end of test: 32 threads, 451 fds open.

After this PR, at end of test: 1 thread, 48 fds open.

This is part of PR #3397 shutdown tidyup.

# Description

Please include a summary of the change and (optionally) which issue is
fixed. Please also include
relevant motivation and context.

# Changed Behaviour

nothing should be really visible to normal users. Increased CPU usage in
the above documented situations.

## Type of change

- New feature
- Code maintenance/cleanup
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
1 participant
@benclifford