Log file writing failure with threadstats

[ahamaline]

When I run Tform on my Windows laptop using WSL, the log file suddenly stops being updated at some point during the calculation, at a point when the workers are running. This has happened for me on all of the 4 occasions when Threadstats was turned on, but not otherwise. The computation itself continues without a problem.

My guess is that there is a problem with the way WSL handles the the race conditions when several threads are trying to write to the file at the same time.

[tueda]

Thank you for your report. To better understand and address the issue, could you provide more specific details? For example,

• Which version of WSL are you using? (WSL1 or WSL2, perhaps with WSL kernel/Windows version)
• Which version of FORM are you working with? (4.3.1 or 5.0.0-beta)
• It would be extremely helpful if you could provide a minimal example that reproduces the issue.

[ahamaline]

The top line on my terminal reads
Welcome to Ubuntu 22.04.3 LTS (GNU/Linux 5.15.133.1-microsoft-standard-WSL2 x86_64)
The Windows version is Windows 11 version 22H2.

My FORM version is 5.0.0-beta.

I'm afraid I won't be able to work on producing a minimal example right now, life is busy...

[ahamaline]

Reporting that I tried swapping the FORM version to the one in the Git branch "4.3"; version 4.3.1. I got the same behavior as I described above.

[ahamaline]

So it turns out that I am having similar problems running my job on a native Linux system, an HPC cluster running Rocky Linux 8.
I changed the title on the issue accordingly. The log file stops being updated at a "difficult" point in the run, while the computation itself continues. In these cases the computation itself stopped a few hours later, but without a logfile I have no idea why.

I don't think the logfile issue is likely to be due to a bug in my code, since it has happened at several different points in the computation. The only thing that seems potentially non-standard about my job is that I call TFORM from within Python, using subprocess.run, rather than from the terminal.

One clue: the last entry in the log file, in each of these incidents, was a "terms left" statistic reported by one of the workers, indicating that its small buffer was filled. I think that in each case it was the first time this happened in the job. Conversely, StageSort had been called before several times by each of the workers without a problem.

I am interested in trying to produce a minimal example to help you debug this, but the truth is I don't really know how to go about doing that; I would just be trying random things blindly. Perhaps you can provide some guidance about what sort of things to try?

[tueda]

Thank you for the update. I think one thing we need to confirm is whether the problem occurs in the absence of Python.

One clue: the last entry in the log file, in each of these incidents, was a "terms left" statistic reported by one of the workers, indicating that its small buffer was filled. I think that in each case it was the first time this happened in the job. Conversely, StageSort had been called before several times by each of the workers without a problem.

I am interested in trying to produce a minimal example to help you debug this

Is it possible for you to provide

1. some of the last lines, say 10 lines, of the stopped log files, so we can see what you exactly see,
2. the code that reproduces the issue, if you can share it. Size is no problem, though smaller is better. You can use "Attach files" or other services like GitHub Gists if the files are big.

[jodavies]

Just to check: is this a log file generated with -l or by redirecting stdout to a file?

[ahamaline]

It is generated with the -f flag in the TFORM call.

Right now I am trying it without Python; I will upload the files when I see the outcome.

[ahamaline]

It turns out that the issue does not occur when I call TFORM directly from the command line, nor when I do so through Python, by calling python3 and then
>>>import subprocess
>>>p=subprocess.run(("tform -w4 -f A_A_A_A.frm").split(),stdout=subprocess.PIPE, stderr=subprocess.PIPE, check=True)

which is the same syntax as the call in my program. It only occurs when I run the program itself. I have no idea what the difference could be.

The program is MatchMakerEFT by Jose Santiago's group at the University of Granada, with some minor changes of my own. It computes the Wilson Coefficients for the EFT in terms of the parameters of a UV model. It uses Feynrules to get the Feynman Rules for two models (UV and EFT), calls QGRAF to get the relevant diagrams, computes their amplitudes in FORM, and does the matching calculation in Mathematica, with all of these being called by Python.

One of my changes was calling TFORM instead of FORM. I don't know why the authors did not do this; perhaps they tried and had the same trouble I am having...

I doubt you want to install the dependencies and run the full program, so I am sending only the files that are involved in the TFORM call. In this example we are computing the one-loop four-photon amplitude in QED, to fourth (lowest) order in the momenta.
A_A_A_A_form.zip

The call is on line 150 of run_form.py, which calls the FORM program A_A_A_A.frm. The formula to be computed is given in A_A_A_A.aux, and the calculation itself is in procedures.h. The main part of the amplitude is printed in the output file A_A_A_A.out, but there is a numerical coefficient that is supposed to appear as the last line of the log file A_A_A_A.log. So failure to complete the log file ruins the result, even though the .out file is correct. I am also including the good log file that I got when calling TFORM from Python outside the program, which I renamed to A_A_A_A_good.log.

The only change that is needed in order to run the computation outside of MatchMakerEFT is to change the path for the procedures.h files, on line 3 of A_A_A_A.frm.

[jodavies]

I am confused by -F actually: the manual states that output should only be to the log, and no statistics should be printed. Rather I get an output on screen, without statistics, and output with statistics in the log.

For your files: is A_A_A_A.frm supposed to be present in the directory, or is it generated? So far I did not get the python code to run. I had to copy a few extra files from the libs dir of the matchmaker repo.

[ahamaline]

Oh, I'm so sorry, the .frm file got left out of the zip by accident. I fixed it now, as an edit to my previous reply.

I indeed do not get any output to the console with the -f flag, but I do get statistics in the log file. This is probably because I have On Statistics; explicitly, in generaldefs.h.

I'm sorry if I gave the impression that you would be able to run the Python code as is! I only included run_form.py so that you could see the TFORM call in its context, in case there is some clue there. If you want to actually run the Python code you will probably need to install MatchMakerEFT and its dependencies and create the models from my .fr files. Let me know if you want to do that and I'll provide some instructions and the files.

[tueda]

Actually, I didn't know the exact behaviour of -f and -F options, niether...

The following code

L F = 1;
P;
.end

prints F to stdout even if -f or -F is used.

On the other hand,

L F = 1;
P +f;
.end

doesn't print F to stdout when -f or -F option is used.

I combined the provided files into one file. This file uses print +f at the end, so if I put -F then it must not give any output.

Then the problem is that somehow v5.0.0-beta.1-30-ge99543a prints, with the -F option (tform -w24 -F test.frm), in most cases,

   amplAAAA =
       - 1/315*esfull(1);

to stdout and then test.log stopped at

             Thread 22 reporting
Time =       4.13 sec    Generated terms =     861185
           expr1    5017 Terms left      =       5488
                         Bytes used      =     345224

To me, somehow 5.0beta with -f or 4.3 (v4.3.1-16-g86e5def) with -f and -F don't print amplAAAA to stdout (it's written into test.log). Weird...

Edit: by the way, thank you for providing your files, @ahamaline!

[ahamaline]

Oh dear, I see that the .aux file I provided only contains the formula for one of the six diagrams. I apologize. I've fixed it now in another edit to that comment. That explains why the numerical coefficient you get is different from mine in A_A_A_A_good.log. Actually, I'd expect that if you run it without some of the diagrams you should be left at the end with unused terms expr2+...+expr6 ; I'm not sure why that doesn't appear in your output.

I'm glad to see you were able to reproduce the bug of the logfile stopping! So apparently it can happen without Python as well. Perhaps it is simply a matter of chance that I didn't get the problem when running outside of MME? But if it's random, why does it have the regularity of happening at the first "terms left" statistic?

Note by the way that in my case that happened on the second diagram; I guess the result of the first diagram was still taking up space in the small buffer. Also note that the issue does not occur with the default setting for the small buffer size. My form.set (computed by Formset) makes the buffers rather small, in accordance with the available memory on my laptop.

As for outputs to stdout - I did not see any such outputs, neither when running directly, nor through Python.

[jodavies]

Running @tueda 's file on my machine, I get the same behaviour on the master branch with -F. Not with tvorm though, there I have nothing on stdout, and no thread statistics in the log (only the master statistics).

[ahamaline]

Did the log file stop for you as well? And if so, did it happen immediately after the first "terms left"?