WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power

[stas00]

@benoit-cty - Can we hold off on 2.0 release?

I'm now testing on the live multi-node setup and I'm getting bombarded by:

WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:09:23 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:09:38 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:09:53 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:10:08 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:10:23 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:10:38 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:10:53 CEST)" skipped: maximum number of running instances reached (1)
WARNING:apscheduler.scheduler:Execution of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:11:08 CEST)" skipped: maximum number of running instances reached (1)

every few secs.

What is wrong and how do I fix this?

this problem wasn't there when I was last testing your PR on my machine (a single node), so perhaps this is something specific to the target HPC.

You can see how the tracker has been initialized here:

https://github.com/bigscience-workshop/Megatron-DeepSpeed/blob/350fb903935f900f400f140d157165d5fa4d7645/megatron/global_vars.py#L170-L175

Thank you!

[benoit-cty]

Well, we will have a look tomorrow (almost midnight here ;) but you could try to increase parameter measure_power_secs to 60 for example.
I think it's 15 by default.

[stas00]

Tomorrow is perfect, @benoit-cty

It looked like it was dumping it every few secs and not 15. But the issue seems to be "maximum number of running instances reached"

Perhaps it was dumping it from each process and that's why it was so much. It was just 16 gpus. In production it's going to be 512 of these, so that's why we want to make sure none of these warnings are reported.

and also added another problem at the end of OP.

Thank you.

[stas00]

Other than the warnings the rest seems to work correctly - saving the emissions at checkpoints - appending to per-rank emission files just fine.

[stas00]

The main warning seems to come and go from restart to restart - sometimes it keeps bombarding every sec, other times it's quiet for a while and then gives a burst in one sec:

WARNING:apscheduler.executors.default:Run time of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:43:10 CEST)" was missed by 0:00:01.973993
WARNING:apscheduler.executors.default:Run time of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:43:10 CEST)" was missed by 0:00:02.064053
WARNING:apscheduler.executors.default:Run time of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:43:11 CEST)" was missed by 0:00:02.024064
WARNING:apscheduler.executors.default:Run time of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:43:10 CEST)" was missed by 0:00:02.303557
WARNING:apscheduler.executors.default:Run time of job "BaseEmissionsTracker._measure_power (trigger: interval[0:00:15], next run at: 2021-08-25 23:43:11 CEST)" was missed by 0:00:02.316997

It's hard to tell from which of the nodes/processes it sent the warning. In this experiment I'm using 4 nodes of 4 gpus - so 16 processes.

May be the user could optionally provide a custom preamble that will identify the rank of the process when any warnings or errors are printed?

[vict0rsch]

Thanks for the details. I am not familiar with multi-node HPC infrastructures so it's hard for me to help but I can definitely make a PR to have a custom logging preamble.

Looking at https://stackoverflow.com/questions/30235604/next-run-time-missed-by-some-seconds-in-job-scheduling-in-apscheuler I can also add a misfire_grace_time param? This may help

[benoit-cty]

Hello,
I was not able to reproduce, even with measure_power_secs=1

You could also probably mask them with:
logging.getLogger('apscheduler.scheduler').level = logging.ERROR

Victor proposition is a better idea.

[stas00]

But won't that just mask an error and result in incorrect emission results?

[vict0rsch]

Fixed in #241