Hi, all, I have met a problem about job running time. My job running
time test script:
```
[root@slurmctl tmp]# cat test.sh
#!/bin/bash
cleanup()
{
local now=$(date '+%s')
echo "now: $(date -d "@$now")"
echo "difference(start_time-now): $((now - start_time))"
}
trap cleanup EXIT
start_time=$(date '+%s')
echo "sleep 90 second ... start_time: $start_time $(date -d "@$start_time")"
sleep 90
```
Submit job with srun(21.08.6 version):
```
[root@slurmctl tmp]# sinfo
PARTITION AVAIL TIMELIMIT NODES STATE NODELIST
debug up 5-00:00:00 2 idle c[3-4]
normal* up 5-00:00:00 2 idle c[1-2]
# Expected difference is 60, but getting different value
[root@slurmctl tmp]# srun --time '0-00:01:00' --nodelist c1 bash test.sh
sleep 90 second ... start_time: 1672823271 Wed Jan 4 17:07:51 CST 2023
srun: Force Terminated job 4
srun: Job step aborted: Waiting up to 5 seconds for job step to finish.
slurmstepd: error: *** STEP 4.0 ON c1 CANCELLED AT 2023-01-04T17:09:00
DUE TO TIME LIMIT ***
test.sh: line 6: 26797 Terminated sleep 90
now: Wed Jan 4 17:09:00 CST 2023
difference(start_time-now): 69 <==========
srun: error: c1: task 0: Terminated
[root@slurmctl tmp]# srun --time '0-00:01:00' --nodelist c1 bash test.sh
sleep 90 second ... start_time: 1672823359 Wed Jan 4 17:09:19 CST 2023
srun: Force Terminated job 5
srun: Job step aborted: Waiting up to 5 seconds for job step to finish.
slurmstepd: error: *** STEP 5.0 ON c1 CANCELLED AT 2023-01-04T17:10:30
DUE TO TIME LIMIT ***
test.sh: line 6: 26879 Terminated sleep 90
now: Wed Jan 4 17:10:30 CST 2023
difference(start_time-now): 71 <==========
srun: error: c1: task 0: Terminated
```
I add `-vvvvvvv` to see debug message for srun, and I look through
some code about extra waiting time explanation and have added debug
message for explanation what to do. After compiling and make install,
I have saw that `poll()` is waiting IO(since timeout is -1 and means
an infinite timeout)
```
[root@slurmctl slurm-repo]# git branch -vvvv
* (no branch) 45e8cd46f2 Update META for v21.08.6 release.
[root@slurmctl slurm-repo]# git diff --unified=1
diff --git a/src/common/eio.c b/src/common/eio.c
index f50d01bc9f..ceb425ae31 100644
--- a/src/common/eio.c
+++ b/src/common/eio.c
@@ -313,2 +313,3 @@ int eio_handle_mainloop(eio_handle_t *eio)
shutdown_time = eio->shutdown_time;
+ debug4("---------------- debug shutdown_time: %d || %d and
then start poll", shutdown_time, eio->shutdown_wait);
slurm_mutex_unlock(&eio->shutdown_mutex);
@@ -316,2 +317,3 @@ int eio_handle_mainloop(eio_handle_t *eio)
goto error;
+ debug4("---------------- debug shutdown_time: %d || %d and
then finish poll", shutdown_time, eio->shutdown_wait);
```
https://github.com/SchedMD/slurm/blob/slurm-20-11-8-1/src/api/step_io.c
... ...
cio->eio = eio_handle_create(slurm_conf.eio_timeout);
... ...
https://github.com/SchedMD/slurm/blob/slurm-20-11-8-1/src/common/eio.c
... ...
/* Get shutdown_time to pass to _poll_internal */
slurm_mutex_lock(&eio->shutdown_mutex);
shutdown_time = eio->shutdown_time;
slurm_mutex_unlock(&eio->shutdown_mutex);
if (_poll_internal(pollfds, nfds, shutdown_time) < 0)
goto error;
... ...
```
[root@slurmctl slurm-repo]# scontrol show config | grep -E -i
"killwait|eiotimeout"
EioTimeout = 1
KillWait = 3 sec
[root@slurmctl tmp]# srun -vvvvvvv --time '0-00:01:00' --nodelist c1
bash test.sh
... ...
srun: debug: Entering _msg_thr_create()
srun: debug4: eio: handling events for 2 objects
srun: debug3: eio_message_socket_readable: shutdown 0 fd 11
srun: debug3: eio_message_socket_readable: shutdown 0 fd 7
srun: debug4: ---------------- debug shutdown_time: 0 || 1 and then start poll
srun: debug: initialized stdio listening socket, port 34940
srun: debug: Started IO server thread (140320727525120)
srun: debug: Entering _launch_tasks
srun: debug3: IO thread pid = 3164
... ...
srun: debug2: Entering _file_write
sleep 90 second ... start_time: 1672823800 Wed Jan 4 17:16:40 CST 2023
srun: debug3: wrote 72 bytes
srun: debug2: Leaving _file_write
... ....
srun: debug3: received timeout message
srun: job time limit to be reached at Wed Jan 04 17:17:40 2023 <===========
srun: debug4: eio: handling events for 1 objects
... ...
srun: debug4: ---------------- debug shutdown_time: 0 || 1 and then start poll
srun:
debug4: ---------------- debug shutdown_time: 0 || 1 and then finish
poll <===== waiting for a moment
srun: debug3: eio_message_socket_accept: start
srun: debug2: eio_message_socket_accept: got message connection from
172.17.0.2:33268 16
srun: debug3: received timeout message
srun: debug4: eio: handling events for 1 objects
srun: debug3: eio_message_socket_readable: shutdown 0 fd 4
srun: debug4: ---------------- debug shutdown_time: 0 || 1 and then start poll
srun: debug4: ---------------- debug shutdown_time: 0 || 1 and then finish poll
srun: debug3: eio_message_socket_accept: start
srun: debug2: eio_message_socket_accept: got message connection from
172.17.0.2:39052 16
srun: debug2: received job step timeout message
srun: debug4: eio: handling events for 2 objects
srun: debug3: eio_message_socket_readable: shutdown 0 fd 11
srun: debug3: eio_message_socket_readable: shutdown 0 fd 7
srun: debug4: ---------------- debug shutdown_time: 0 || 1 and then start poll
srun: debug4:
---------------- debug shutdown_time: 0 || 1 and then finish poll
<===== waiting for a moment
... ...
```
So:
* How to set an non-infinite timeout for _poll_internal()? Support
configuration?
* Or how to avoid extra EIO event time cost for job running time for
--time, there is a bug for --time option?
Thanks!
