Scheduler experienced prolonged stall after midnight

[eddiewang927]

Description

Hi,
I would like to ask for your insights on an intermittent issue we are seeing in our cluster.

Every day, within a very specific time window 00:05–00:11, any client command such as:

• qsub

• qrsh

will randomly fail and return:

failed receiving gdi request response for mid=1 (got syncron message receive timeout error)

After 00:11, everything immediately returns to normal.

If you have any ideas—possible internal tasks running at that time, known behaviors, or pointers to where we should investigate—your suggestions would be greatly appreciated.

Thanks!

[eddiewang927]

Hi

I'd like to add o focused update to help triage the Jan 22 (CST) scheduling/state-transition issue:

What we see

• Incident window: 00:00–00:11 on 2026-01-22. During this period, jobs accumulated in qw and t, and state transitions slowed down. In the analyzed window, no r was observed in the per-second distinct counts (i.e., r=0).
• Catch-up behavior: at 00:11:19 there is a visible “catch-up” where queued qw jobs are drained quickly; the last snapshot in the log is 00:11:22.
• Cut-point job (3440715): qsub_time is 00:02:31.138956; we observe qw→t at 00:06:35. Based on first-seen timestamps, qw→t latency ≈ 244 s.
• qmaster message (HUP 1) for 3440715.1:

  2026-01-22 00:10:34.960600|      worker|03|rdocs01|W|job 3440715.1 failed on host rd6647  assumedly after job because: job 3440715.1 died through signal HUP (1)
  

Impact

• Jobs lingered in qw / t, reducing scheduling throughput and stretching end-to-end turnaround. The absence of r in the window highlights that execution did not proceed normally in this period.
• Around the 3440715 cut-point, the observed qw→t latency (~244 s) and the 00:11:19 catch-up suggest a temporary scheduler/state-transition stall followed by recovery.
• Starting with job 3440715, whenever a job transitioned to r it would fail immediately, and the failure carried the same qmaster signature as for 3440715 (signal HUP (1)).
• Job only started succeeding again for submissions made aggter 00:11:19 (CST). The last snapshot in th provided log is 00:11:22, which marks the tail of the incident window we captured.

Job 3440715 — Details (as provided)

jobnumber                          3440715
qsub_time                          2026-01-22 00:02:31.138956

start_time                         2026-01-22 00:06:35.359267
end_time                           2026-01-22 00:06:37.367464
failed                             100 : assumedly after job
exit_status                        129

Note: From snapshots, first-seen qw→t implies ~244 s latency (00:02:32 → 00:06:36).

Timeline (CST)

• 00:00:00 — qw / t begin to accumulate; state transitions slow.
• 00:02:31.138 — Job 3440715 submitted (qsub_time).
• 00:06:35 — Job 3440715 observed qw→t (~244 s latency).
• 00:10:34.960600 — qmaster logs job 3440715.1 failed with signal HUP (1) (see message above).
• 00:11:19 — Queued qw drained in a short burst (catch-up).
• 00:11:22 — Last snapshot in the provided log window.

Attachments

• Raw log data: ocs_log.txt (basis of analysis; window ends at 00:11:22).

ocs_log.txt

Note1: rd1215 host info was used only as a liveness check to see whether qhost was responsive; it is not diagnostic and should not be as cluster capacity/performance evidence.
Note2: please ignore hqw - it is a user-side hold (-h) applied when a user submits too many jobs intended to run concurrently in r, and it is not diagnostic; also, thn number of r jobs is not recorded in this log.

[jgabler-hpc]

Hi Elmo,

thank you for this excellent report.

In general I can imagine 2 sources for such a slowdown: sge_qmaster internal processing and external factors.

1 - sge_qmaster internal
For sge_qmaster internal processing I am aware of only one mechanism which is active shortly after midnight,
that is the generation of intermediate accounting records.
Intermediate accounting records are generated for long running jobs.
They allow to do job usage reports on a per day basis, e.g., from a reporting database.
The mechanism generating these intermediate reporting records is only active, if you have reporting enabled, see global configuration, reporting_params, attribute reporting, e.g.

reporting_params             accounting=true reporting=true \
                             flush_time=00:00:05 joblog=true sharelog=00:10:00

The mechanism

• is active from 00:00 until max. 00:10
• writes an intermediate record per job / array task / pe task once, when a job report is received from an sge_execd.
• usually it has finished all intermediate records within one load_report_time

The time frame corresponds pretty well with what you observe, OTOH

• it is a "cheap" operation, unless you have a huge amount of running jobs, it should not be noticeable at all
• it should not have any impact on read only requests (qstat, qhost), which are handled by a separate thread pool

Do you have reporting enabled?
How many running jobs are there when you observe the issue?

2 - sge_qmaster external
The second possible source would be something external.
Having impact on sge_qmaster would be anything which

• slows down file system operation, esp. if your sge_qmaster does spooling on a shared filesystem
• slows down network operations
• produces high cpu load on the sge_qmaster host

My guess would be a spooling filesystem slowdown, e.g., due do some cron job starting at midnight.
In this case spooling operations of sge_qmaster would be delayed,
which would slow down processing of reports and requests,
the request queues filling up,
finally leading to timeouts.

You can use qping to monitor the length of message queues, e.g.,

$ qping -info <hostname> $SGE_QMASTER_PORT qmaster 1
2026-01-22 10:10:12.543652:
SIRM version:             0.1
SIRM message id:          1
start time:               2026-01-22 08:04:52.000000 (1769065492000000)
run time [s]:             7520
messages in read buffer:  0
messages in write buffer: 0
nr. of connected clients: 6
...

If there is a slowdown in filesystem operations, you would probably see a high io wait time being reported by top.
Tools like dstat might be helpful in understanding the load situation on the host.

Best regards,

Joachim

[eddiewang927]

Hi Joachim,

Thank you again for your detailed analysis.

To clarify the configuration details, especially regarding your question about reporting, here are the relevant settings from our global configuration

qmaster_params               ENABLE_QMASTER_THREADS=true
execd_params                 ENABLE_ADDGRP_KILL=true ENABLE_BINDING=true \
                             S_DESCRIPTORS=15536 H_DESCRIPTORS=15536
reporting_params             accounting=true reporting=false \
                             flush_time=00:00:1 joblog=false sharelog=00:00:00
finished_jobs                100

[jgabler-hpc]

Hi Elmo,

thank you for confirming that it is not the intermediate reporting records.

I stumbled over the qmaster_params ENABLE_QMASTER_THREADS=true,
this is not a qmaster_param of Open Cluster Scheduler.
Is this "inherited" from an earlier Gridengine version? Which one did you use before?
It will not have any effect on OCS - it will also not do any harm, though.

[eddiewang927]

Hi Joachim,

Thanks for the clarification!

Regarding your question about the origin of ENABLE_QMASTER_THREADS=true:

My previous environments were running Grid Engine 2011.11p1 and Sun Grid Engine 6.2u2. We didn't use this parameter in those versions either.

To be honest, this line was actually suggested to me by an LLM (AI) while I was setting up and testing OCS. It seems the AI "hallucinated" a Univa Grid Engine parameter and confidently told me to put it into my OCS configuration! :)

Good to know it is ignored and does no harm. I will focus my troubleshooting on the "External Factors" you mentioned, specifically monitoring the filesystem I/O and latency around midnight.

[eddiewang927]

Hi Joachim,

I would like to add a focused update regarding the scheduling/state-transition issue observed on Jan 22.

Based on further investigation and analyzing the qmaster behavior alongside the source code (ocs_ReportingFileWriter.cc and sge_reporting_qmaster.cc) with the assistance of Gemini, I believe I have identified the potential root cause: Severe Mutex Lock Contention caused by an aggressive flush_time setting interacting with the midnight intermediate accounting window.

Here are my detailed observations and the hypothesis derived from the code analysis:

1. Observation: "Off-CPU" Behavior

During the incident window (00:00:00 – 00:10:00), I observed that the qmaster CPU usage **dropped significantly **, while the system became unresponsive (jobs accumulating in qw, timeouts causing HUP failures).

This indicates that the qmaster main thread was not CPU-bound (busy computing) but was Blocked/Sleeping, likely waiting to acquire a lock (suspected to be the global writer_mutex).

2. Code Analysis & Hypothesis

Using Gemini to analyze the logic in ocs_ReportingFileWriter.cc, we found a critical interaction:

• The "Zombie" Logic: Even with reporting=false, the function is_intermediate_acct_required appears to still be executed for every job report. The code logic checks the time before checking the configuration switch.
• The Midnight Window: Inside this function, the condition if (tm_now.tm_hour != 0 || tm_now.tm_min > INTERMEDIATE_ACCT_WINDOW) restricts the execution of extra calculation logic to the window between 00:00 and 00:10. During this window, the main thread performs these calculations for every running job, inevitably increasing the time it holds locks.
• The Conflict: My configuration was set to flush_time=00:00:01. This forces the Accounting Writer thread to wake up and attempt to acquire the writer_mutex every second.

The Conclusion:
The combination of the Midnight Computational Overhead (main thread holding locks longer) and the High-Frequency Flush (writer thread spamming lock requests every 1s) likely created a "Lock Convoy" scenario.

The system recovery at 00:11:19 aligns perfectly with the closing of the INTERMEDIATE_ACCT_WINDOW (default 10 minutes), which stops the execution of the extra midnight logic.

3. Action Plan

To reduce the frequency of lock contention, I am applying the following configuration change today:

- reporting_params accounting=true reporting=false flush_time=00:00:1 ...
+ reporting_params accounting=true reporting=false flush_time=00:01:00 ...

The detailed source code analysis above was assisted by AI (Gemini). While it logically explains the observed phenomena, the possibility of AI hallucination or misinterpretation cannot be ruled out. Therefore, I will prioritize applying the aforementioned configuration change (flush_time) to empirically verify this hypothesis based on actual system performance.

[eddiewang927]

Update: flush_time fix failed; previous hypothesis likely incorrect.

I applied the flush_time=00:01:00 change, but the system instability and "lock-up" behavior during 00:00 – 00:10 persists exactly as before.

It appears that the previous AI-assisted hypothesis regarding flush_time causing high-frequency lock contention was likely incorrect (an AI hallucination) or a red herring. Adjusting this parameter had zero impact on the incident.

Here are the purely observed metrics regarding the environment and resource usage during the incident window, which point to a different root cause:

1. Workload Context:

• There are approximately 9,000 running jobs on the system.

2. Memory (Stable):

• Memory usage remains flat during the incident.
• There is no change in Swap activity (no si/so spikes). This rules out memory thrashing.

3. CPU Usage Pattern (Significant Drop):

• Normal Operation: qmaster CPU usage hovers around 200% (effectively utilizing 2-3 cores).
• During Incident (00:00-00:10): CPU usage DROPS to 50-80%.

[eddiewang927]

Hi Joachim,

I've been analyzing the code to debug a midnight performance freeze on my cluster (which has around 9,000 running jobs). I'm not an expert in C, but with some assistance from Gemini, I've looked into ocs_ReportingFileWriter.cc and would like to verify my understanding with you.

It appears that setting reporting=false only prevents the final step of writing the file to disk, but it does not prevent the intermediate accounting calculations from running.

My observation of the logic flow at 00:00 is:

1. The is_intermediate_acct_required function is triggered for every running job.
2. Inside this function, it performs calculations for the 10-minute window.
3. Only after these calculations are done does the code check if a writer exists (which is null when reporting=false), effectively discarding the result.

If my understanding is correct, the system is serializing these heavy calculations for all 9,000 jobs under the Global Lock every midnight, causing the freeze, even though reporting is disabled.

Could you confirm if this is indeed the case?

Best regards,

[eddiewang927]

Hi Joachim,

I found something interesting that might explain the issue.

I checked the sge_reporting_qmaster.c in the daimh/sge repository, and I see that the optimization check is indeed present in the original C implementation:

https://github.com/daimh/sge/blob/master/source/daemons/qmaster/sge_reporting_qmaster.c#L1051

/* sge_reporting_qmaster.c @ line 1051 */
if (!mconf_get_do_reporting()) {
   DRETURN(false);
}

However, in the C++ implementation (ocs_ReportingFileWriter.cc) that my cluster is using, this check appears to be missing at the beginning of is_intermediate_acct_required.
It looks like when the logic was ported from C to C++ (OCS), this specific optimization was accidentally dropped, causing the midnight performance regression even when reporting=false.
Could you confirm if this is a regression in the OCS C++ code?

[jgabler-hpc]

Hi Elmo,

thank you for doing this further analysis!

And you are right, this code might be the root cause for the issue you are seeing.

Not because the time calculation would be expensive,
but because in the lines following the
ocs::ReportingFileWriter::create_acct_records()
it is spooling the job/array task/pe task, even if it did not create an intermediate accounting record.

If you have spooling on a shared file system, e.g., for a HA setup,
then spooling operations can be expensive, depending on the performance of the shared file system.

And it will run the code / do the spooling whenever a job report for a running job comes in, even multiple times per job.
With reporting enabled, it would run the code only once - which it must be able to cope with.

What is the load_report_time configured in your global configuration?
If it is rather short, increasing it should mitigate the issue.

We will fix this issue for the next patch.

Thanks,

Joachim

[eddiewang927]

Hi Joachim,
Thank you for the detailed explanation regarding the spooling behavior.
Just to add some context regarding the storage environment: Our OCS spool is hosted on a NetApp A800 All-Flash array.
I checked the performance metrics on the A800 during the reported window (00:00 - 00:10), and everything looked normal with no signs of stress on the storage side.
Since the storage backend itself was not saturated, it seems possible that we might be hitting the inherent latency limits of the NFS protocol (network round-trip times) rather than a disk throughput issue.
As a temporary mitigation, I will follow your advice and increase the load_report_time. I plan to change it from the current 00:01:00 to 00:05:00.
One question regarding this change:
Apart from the expected delay in load updates for the scheduler and qhost, are there any other major side effects or internal mechanisms I should be aware of when increasing load_report_time to 5 minutes?

Best regards,

[jgabler-hpc]

Hi Elmo,

when increasing the load_report_time, make sure that the max_unheard has a higher value than load_report_time.

When sge_qmaster doesn't receive a load report from an sge_execd within max_unheard, then it is setting this sge_execd / all queue instances on the host in unknown state, meaning no jobs would be scheduled to this host.

Best regards,

Joachim

[jgabler-hpc]

Hi Elmo,

the issue is fixed in the 9.0.11 release which is available now.
Please give it a try and let us know if it fixes your issue.

Best regards,

Joachim