Reproduce time gap, fix

[geoffgeoffgeoff3]

Understand why WC time passes by but no CPU time. Seems to be inside containerised provers. Fix.

[jackeown]

So far, I was able to verify this issue by running a job using run_image_k8s.py inside the head node container.

Now I'm trying to reproduce it in k8s just running run_image_k8s.py from my laptop (connected to the same k8s cluster).

If I can do that, then I'll try just running the theorem proving image itself outside of k8s and see if I can reproduce it there.

[jackeown]

I was able to run E with run_image_k8s.py on my laptop and sometimes got the same output I was getting in starexec:

0.00/0.03 Running first-order theorem proving
0.00/0.03 Running: /artifacts/eprover --delete-bad-limit=2000000000 --definitional-cn
f=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=
60 /tmp/tmp.6XgtNkH0Z5/E---3.1_19.p
60.02/40.41 # Version: 3.0.03-DEBUG
60.02/40.41 # Preprocessing class: FSMSSMSSSSSNFFN.
60.02/40.41 # Scheduled 4 strats onto 8 cores with 60 seconds (480 total)
60.02/40.41 # Starting G-E--_208_C18_F1_SE_CS_SOS_SP_PS_S5PRR_RG_S04AN with 300s (5) co
res
60.02/40.41 # Starting new_bool_3 with 60s (1) cores
60.02/40.41 # Starting new_bool_1 with 60s (1) cores
60.02/40.41 # Starting sh5l with 60s (1) cores
60.02/40.41 # sh5l with pid 36 completed with status 0
60.02/40.41 # Result found by sh5l
60.02/40.41 # Preprocessing class: FSMSSMSSSSSNFFN.
60.02/40.41 # Scheduled 4 strats onto 8 cores with 60 seconds (480 total)
...

However, I don't get the same experience using run_image.py, but I get a small delay still:

0.00/0.05 Running first-order theorem proving
0.00/0.05 Running: ./eprover --delete-bad-limit=2000000000 --definitional-cnf=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=30 /tmp/tmp.DH4wYaduBf/E---3.1_14.p
0.48/0.58 # Version: 3.0.03-DEBUG
0.48/0.58 # Preprocessing class: FSMSSMSSSSSNFFN.
0.48/0.58 # Scheduled 4 strats onto 8 cores with 30 seconds (240 total)
0.48/0.58 # Starting G-E--_208_C18_F1_SE_CS_SOS_SP_PS_S5PRR_RG_S04AN with 150s (5) cores
0.48/0.58 # Starting new_bool_3 with 30s (1) cores
0.48/0.58 # Starting new_bool_1 with 30s (1) cores
0.48/0.58 # Starting sh5l with 30s (1) cores
0.48/0.58 # sh5l with pid 31 completed with status 0
0.48/0.58 # Result found by sh5l
0.48/0.58 # Preprocessing class: FSMSSMSSSSSNFFN.
0.48/0.58 # Scheduled 4 strats onto 8 cores with 30 seconds (240 total)

So there's something about running in k8s that is causing a larger delay.
This is very strange because it's after k8s starts running the job because the delay happens between "Running /artifacts/eprover ..." and the first line of output from E (which both are coming from the entrypoint of the theorem prover image).

@geoffgeoffgeoff3 How is E called from docker.io/tptpstarexec/eprover:3.0.03-RLR-amd64? What is the series of scripts/processes that are run? Do you have any ideas here? My current theory is that when E is started inside of whatever eprover image entrypoint, the EC2 it's running on can't schedule that new process or something...

[jackeown]

Another possibility could be that it's related to the fact that Eprover is multithreaded (trying to use 8 cores) and the k8s job is limiting it to "1500m" CPU.

[geoffgeoffgeoff3]

I was able to run E with **run_image_k8s.py** on my laptop and sometimes got the same output I was getting in starexec: > 0.00/0.03 Running first-order theorem proving 0.00/0.03 Running: /artifacts/eprover --delete-bad-limit=2000000000 --definitional-cn f=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=60 /tmp/tmp.6XgtNkH0Z5/E---3.1_19.p 60.02/40.41 # Version: 3.0.03-DEBUG ... However, I don't get the same experience using **run_image.py**, but I get a small delay still: > 0.00/0.05 Running first-order theorem proving 0.00/0.05 Running: ./eprover --delete-bad-limit=2000000000 --definitional-cnf=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=30 /tmp/tmp.DH4wYaduBf/E---3.1_14.p 0.48/0.58 # Version: 3.0.03-DEBUG

The delay is fine, it's the offset between the WC and CPU at the first report that is of primary concern ... 60.02 - 40.41 = ~20s BAD 0.48 - 0.58 = ~0.1s OK

So there's something about running in k8s that is causing a larger delay. This is very strange because it's after k8s starts running the job because the delay happens between "Running /artifacts/eprover ..." and the first line of output from E (which both are coming from the entrypoint of the theorem prover image).

Hmmm, maybe the buffers need to run hot, no buffering. There is no buffering in E or runsolver, so maybe there's buffering at the k8s level? Is there a flag to say "no buffering of stdout"?

@geoffgeoffgeoff3 How is E called from `docker.io/tptpstarexec/eprover:3.0.03-RLR-amd64`? What is the series of scripts/processes that are run? Do you have any ideas here? My current theory is that when E is started inside of whatever eprover image entrypoint, the EC2 it's running on can't schedule that new process or something...

k8s calls start_RLR start_RLR calls runsolver (which is generic for all systems) runsolver calls run_system (which is specific to the system, here E) run_system calls the system, here the eprover binary

Another possibility could be that it's related to the fact that Eprover is multithreaded (trying to use 8 cores) and the k8s job is limiting it to "1500m"

I don't think so - eprover is smart enough to count the cores.

[jackeown]

So what prints the following? (and runsolver adds the timestamps?):

0.00/0.03 Running first-order theorem proving
0.00/0.03 Running: /artifacts/eprover --delete-bad-limit=2000000000 --definitional-cnf=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=30 /tmp/tmp.uel83NpMTy/E---3.1_19.p

EDIT: Nevermind, it's the run_system script.

[geoffgeoffgeoff3]

So what software prints the following?: > 0.00/0.03 Running first-order theorem proving > 0.00/0.03 Running: /artifacts/eprover --delete-bad-limit=2000000000 --definitional-cnf=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=30 /tmp/tmp.uel83NpMTy/E---3.1_19.p

The output ... Running first-order theorem proving Running: /artifacts/eprover --delete-bad-limit=2000000000 --definitional-cnf=24 -s --print-statistics -R --print-version --proof-object --auto-schedule=8 --cpu-limit=30 /tmp/tmp.uel83NpMTy/E---3.1_19.p ... comes script run_E, which then starts the eprover binary. The output is captured by runsolver, which adds the timestamps on the front.

…

-- Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences) Department of Computer Science, University of Miami, USA http://www.cs.miami.edu/~geoff ------------------------------------------------------------------------------- "My cat" is not a float. Every string should learn to swim. Despite the high cost of living, it's still surprisingly popular. Does superman wonder why we wear our overpants on the inside?

[jackeown]

You were right. It has to do with stdout buffering, which apparently can be fixed by adding "tty: true" to the k8s job template. I'll do that and push the change and I think it'll fix the issue :) It has so far in my testing.

[geoffgeoffgeoff3]

Do you recall if we had that problem in starexec-containerised too? Is there something that we need to do to in that context?

…

-- Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences) Department of Computer Science, University of Miami, USA http://www.cs.miami.edu/~geoff ------------------------------------------------------------------------------- "My cat" is not a float. Every string should learn to swim. Despite the high cost of living, it's still surprisingly popular. Does superman wonder why we wear our overpants on the inside?

[jackeown]

no it's not in any other context. I was able to confirm the issue isn't present if you run a theorem proving image directly in podman using the run_image.py script

…

On Tue, Mar 25, 2025, 10:10 PM Geoff Sutcliffe ***@***.***> wrote: Do you recall if we had that problem in starexec-containerised too? Is there something that we need to do to in that context?<br> <br> -- <br> Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences)<br> Department of Computer Science, University of Miami, USA<br> http://www.cs.miami.edu/~geoff<br> -------------------------------------------------------------------------------<br> &quot;My cat&quot; is not a float. Every string should learn to swim.<br> Despite the high cost of living, it&#39;s still surprisingly popular.<br> Does superman wonder why we wear our overpants on the inside?<br> — Reply to this email directly, view it on GitHub <#19 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAD7C3FASGWONZLAKFIXH7L2WHA3JAVCNFSM6AAAAABYS5EIEOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDONJSGU2TKMZXGE> . You are receiving this because you were assigned.Message ID: ***@***.***> [image: geoffgeoffgeoff3]*geoffgeoffgeoff3* left a comment (StarExecMiami/StarExec-ARC#19) <#19 (comment)> Do you recall if we had that problem in starexec-containerised too? Is there something that we need to do to in that context?<br> <br> -- <br> Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences)<br> Department of Computer Science, University of Miami, USA<br> http://www.cs.miami.edu/~geoff<br> -------------------------------------------------------------------------------<br> &quot;My cat&quot; is not a float. Every string should learn to swim.<br> Despite the high cost of living, it&#39;s still surprisingly popular.<br> Does superman wonder why we wear our overpants on the inside?<br> — Reply to this email directly, view it on GitHub <#19 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAD7C3FASGWONZLAKFIXH7L2WHA3JAVCNFSM6AAAAABYS5EIEOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDONJSGU2TKMZXGE> . You are receiving this because you were assigned.Message ID: ***@***.***>

[geoffgeoffgeoff3]

Can I close the issue?

…

-- Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences) Department of Computer Science, University of Miami, USA http://www.cs.miami.edu/~geoff ------------------------------------------------------------------------------- "My cat" is not a float. Every string should learn to swim. Despite the high cost of living, it's still surprisingly popular. Does superman wonder why we wear our overpants on the inside?

[jackeown]

give me a day to test more but I think so

…

On Tue, Mar 25, 2025, 10:47 PM Geoff Sutcliffe ***@***.***> wrote: Can I close the issue?<br> <br> -- <br> Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences)<br> Department of Computer Science, University of Miami, USA<br> http://www.cs.miami.edu/~geoff<br> -------------------------------------------------------------------------------<br> &quot;My cat&quot; is not a float. Every string should learn to swim.<br> Despite the high cost of living, it&#39;s still surprisingly popular.<br> Does superman wonder why we wear our overpants on the inside?<br> — Reply to this email directly, view it on GitHub <#19 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAD7C3HZS7BPWF5CFSL62GL2WHFIFAVCNFSM6AAAAABYS5EIEOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDONJSGYZDGNRRHA> . You are receiving this because you were assigned.Message ID: ***@***.***> [image: geoffgeoffgeoff3]*geoffgeoffgeoff3* left a comment (StarExecMiami/StarExec-ARC#19) <#19 (comment)> Can I close the issue?<br> <br> -- <br> Geoff Sutcliffe (Pronouns, but also Proverbs, so I can write sentences)<br> Department of Computer Science, University of Miami, USA<br> http://www.cs.miami.edu/~geoff<br> -------------------------------------------------------------------------------<br> &quot;My cat&quot; is not a float. Every string should learn to swim.<br> Despite the high cost of living, it&#39;s still surprisingly popular.<br> Does superman wonder why we wear our overpants on the inside?<br> — Reply to this email directly, view it on GitHub <#19 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAD7C3HZS7BPWF5CFSL62GL2WHFIFAVCNFSM6AAAAABYS5EIEOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDONJSGYZDGNRRHA> . You are receiving this because you were assigned.Message ID: ***@***.***>

[jackeown]

Nevermind...I guess that didn't fix the issue. I'm still having the problem in starexec. I guess I just got lucky when I ran it a few times before...ugh