| Message ID | CAKdteOajXXOc=c+EvhrT-BFjmEOkT2bPwyxpP2g5ibtben=_cA@mail.gmail.com |
|---|---|
| State | New |
| Headers | show |
| Series | Handle timeout warnings in dg-extract-results | expand |
Hi Christophe, > On 23 Jan 2019, at 13:16, Christophe Lyon <christophe.lyon@linaro.org> wrote: > dg-extract-results currently moves lines like > WARNING: program timed out > at the end of each .exp section when it generates .sum files. > > This is because it sorts its output based on the 2nd field, which is > normally the testname as in: > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test > > As you can notice 'program' comes after > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > most (all?) GCC testnames. > > This is a bit of a pain when trying to handle transient test failures > because you can no longer match such a WARNING line to its FAIL > counterpart. > > The attached patch changes this behavior by replacing the line > WARNING: program timed out > with > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test program > timed out > > The effect is that this line will now appear immediately above the > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test > so that it's easier to match them. > > > I'm not sure how much people depend on the .sum format, I also > considered emitting > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > -flto -fno-use-linker-plugin -flto-partition=none execution test > > I also restricted the patch to handling only 'program timed out' > cases, to avoid breaking other things. > > I considered fixing this in Dejagnu, but it seemed more complicated, > and would delay adoption in GCC anyway. > > What do people think about this? It seems a good idea (for those of us with targets prone to timeout issues). I’m going to give it a try on Darwin. Iain > > Thanks, > > Christophe > <dg-extract-results.chlog.txt><dg-extract-results.patch.txt>
On Sat, 26 Jan 2019 at 17:43, Iain Sandoe <idsandoe@googlemail.com> wrote: > > Hi Christophe, > > > On 23 Jan 2019, at 13:16, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > > dg-extract-results currently moves lines like > > WARNING: program timed out > > at the end of each .exp section when it generates .sum files. > > > > This is because it sorts its output based on the 2nd field, which is > > normally the testname as in: > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test > > > > As you can notice 'program' comes after > > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > > most (all?) GCC testnames. > > > > This is a bit of a pain when trying to handle transient test failures > > because you can no longer match such a WARNING line to its FAIL > > counterpart. > > > > The attached patch changes this behavior by replacing the line > > WARNING: program timed out > > with > > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test program > > timed out > > > > The effect is that this line will now appear immediately above the > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test > > so that it's easier to match them. > > > > > > I'm not sure how much people depend on the .sum format, I also > > considered emitting > > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > > -flto -fno-use-linker-plugin -flto-partition=none execution test > > > > I also restricted the patch to handling only 'program timed out' > > cases, to avoid breaking other things. > > > > I considered fixing this in Dejagnu, but it seemed more complicated, > > and would delay adoption in GCC anyway. > > > > What do people think about this? > > It seems a good idea (for those of us with targets prone to timeout issues). > I’m going to give it a try on Darwin. > Thanks for taking a look and confirming I'm not the only one having to face random timeouts :-) Did it work for you? > Iain > > > > Thanks, > > > > Christophe > > <dg-extract-results.chlog.txt><dg-extract-results.patch.txt> >
Hi Christophe, > On 29 Jan 2019, at 09:58, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > On Sat, 26 Jan 2019 at 17:43, Iain Sandoe <idsandoe@googlemail.com> wrote: >> >> Hi Christophe, >> >>> On 23 Jan 2019, at 13:16, Christophe Lyon <christophe.lyon@linaro.org> wrote: >> >>> dg-extract-results currently moves lines like >>> WARNING: program timed out >>> at the end of each .exp section when it generates .sum files. >>> >>> This is because it sorts its output based on the 2nd field, which is >>> normally the testname as in: >>> FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto >>> -fno-use-linker-plugin -flto-partition=none execution test >>> >>> As you can notice 'program' comes after >>> gcc.c-torture/execute/20020129-1.c alphabetically, and generally after >>> most (all?) GCC testnames. >>> >>> This is a bit of a pain when trying to handle transient test failures >>> because you can no longer match such a WARNING line to its FAIL >>> counterpart. >>> >>> The attached patch changes this behavior by replacing the line >>> WARNING: program timed out >>> with >>> WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto >>> -fno-use-linker-plugin -flto-partition=none execution test program >>> timed out >>> >>> The effect is that this line will now appear immediately above the >>> FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto >>> -fno-use-linker-plugin -flto-partition=none execution test >>> so that it's easier to match them. >>> >>> >>> I'm not sure how much people depend on the .sum format, I also >>> considered emitting >>> WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 >>> -flto -fno-use-linker-plugin -flto-partition=none execution test >>> >>> I also restricted the patch to handling only 'program timed out' >>> cases, to avoid breaking other things. >>> >>> I considered fixing this in Dejagnu, but it seemed more complicated, >>> and would delay adoption in GCC anyway. >>> >>> What do people think about this? >> >> It seems a good idea (for those of us with targets prone to timeout issues). >> I’m going to give it a try on Darwin. >> > > Thanks for taking a look and confirming I'm not the only one having to face > random timeouts :-) My worst-cases are a couple of PCH-related that are still unanalysed.. but those are not the only ones. + when I use VMs to cover some of the earlier versions of the system, they are much more prone to occasional timeouts. > Did it work for you? So far it’s looking nice… (anything that makes the dg output more stable is Good in my book) … I am not sure (not checked thoroughly) but I think I saw one case in libgomp testing where it didn’t pick up the timeout, will poke some more at that if i see it again. thanks for the patch! Iain
On Tue, 29 Jan 2019 at 11:12, Iain Sandoe <idsandoe@googlemail.com> wrote: > > Hi Christophe, > > > On 29 Jan 2019, at 09:58, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > > > On Sat, 26 Jan 2019 at 17:43, Iain Sandoe <idsandoe@googlemail.com> wrote: > >> > >> Hi Christophe, > >> > >>> On 23 Jan 2019, at 13:16, Christophe Lyon <christophe.lyon@linaro.org> wrote: > >> > >>> dg-extract-results currently moves lines like > >>> WARNING: program timed out > >>> at the end of each .exp section when it generates .sum files. > >>> > >>> This is because it sorts its output based on the 2nd field, which is > >>> normally the testname as in: > >>> FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > >>> -fno-use-linker-plugin -flto-partition=none execution test > >>> > >>> As you can notice 'program' comes after > >>> gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > >>> most (all?) GCC testnames. > >>> > >>> This is a bit of a pain when trying to handle transient test failures > >>> because you can no longer match such a WARNING line to its FAIL > >>> counterpart. > >>> > >>> The attached patch changes this behavior by replacing the line > >>> WARNING: program timed out > >>> with > >>> WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > >>> -fno-use-linker-plugin -flto-partition=none execution test program > >>> timed out > >>> > >>> The effect is that this line will now appear immediately above the > >>> FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > >>> -fno-use-linker-plugin -flto-partition=none execution test > >>> so that it's easier to match them. > >>> > >>> > >>> I'm not sure how much people depend on the .sum format, I also > >>> considered emitting > >>> WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > >>> -flto -fno-use-linker-plugin -flto-partition=none execution test > >>> > >>> I also restricted the patch to handling only 'program timed out' > >>> cases, to avoid breaking other things. > >>> > >>> I considered fixing this in Dejagnu, but it seemed more complicated, > >>> and would delay adoption in GCC anyway. > >>> > >>> What do people think about this? > >> > >> It seems a good idea (for those of us with targets prone to timeout issues). > >> I’m going to give it a try on Darwin. > >> > > > > Thanks for taking a look and confirming I'm not the only one having to face > > random timeouts :-) > > My worst-cases are a couple of PCH-related that are still unanalysed.. but those are not the only ones. > + when I use VMs to cover some of the earlier versions of the system, they are much more prone to occasional timeouts. > > > Did it work for you? > > So far it’s looking nice… (anything that makes the dg output more stable is Good in my book) > > … I am not sure (not checked thoroughly) but I think I saw one case in libgomp testing where it didn’t pick up the timeout, will poke some more at that if i see it again. If you still have the logs, you can run the script manually. > > thanks for the patch! > Iain >
> On 29 Jan 2019, at 10:22, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > On Tue, 29 Jan 2019 at 11:12, Iain Sandoe <idsandoe@googlemail.com> wrote: >> <SNIP> >>> Did it work for you? >> >> So far it’s looking nice… (anything that makes the dg output more stable is Good in my book) >> >> … I am not sure (not checked thoroughly) but I think I saw one case in libgomp testing where it didn’t pick up the timeout, will poke some more at that if i see it again. > > If you still have the logs, you can run the script manually. So it seems that the only library testsuite that uses dg-extract-results is libstdc++v3. This explains why the script wasn’t applied to libgomp. It DTRT if applied manually. I guess an edit of the various library testsuite Makefile(s) to generate the original .sum file as a temp followed by dg-extract-results to the final file would work. Will try it when I have a few moments (unless you get to it first ;) ) Iain
On Thu, 31 Jan 2019 at 13:30, Iain Sandoe <idsandoe@googlemail.com> wrote: > > > > On 29 Jan 2019, at 10:22, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > > > On Tue, 29 Jan 2019 at 11:12, Iain Sandoe <idsandoe@googlemail.com> wrote: > >> > <SNIP> > > >>> Did it work for you? > >> > >> So far it’s looking nice… (anything that makes the dg output more stable is Good in my book) > >> > >> … I am not sure (not checked thoroughly) but I think I saw one case in libgomp testing where it didn’t pick up the timeout, will poke some more at that if i see it again. > > > > If you still have the logs, you can run the script manually. > > So it seems that the only library testsuite that uses dg-extract-results is libstdc++v3. This explains why the script wasn’t applied to libgomp. It DTRT if applied manually. Good news. I didn't imagine there were differences in the way results are extracted between our various tools/libs. > I guess an edit of the various library testsuite Makefile(s) to generate the original .sum file as a temp followed by dg-extract-results to the final file would work. Will try it when I have a few moments (unless you get to it first ;) ) Please do, I don't plan to check libgomp. Thanks Christophe > > Iain >
On Jan 23, 2019, at 5:16 AM, Christophe Lyon <christophe.lyon@linaro.org> wrote:
> What do people think about this?
Seems reasonable.
On Sat, 2 Feb 2019 at 00:13, Mike Stump <mikestump@comcast.net> wrote: > > On Jan 23, 2019, at 5:16 AM, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > What do people think about this? > > Seems reasonable. Thanks, committed as r268511. Christophe
> On 4 Feb 2019, at 08:55, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > On Sat, 2 Feb 2019 at 00:13, Mike Stump <mikestump@comcast.net> wrote: >> >> On Jan 23, 2019, at 5:16 AM, Christophe Lyon <christophe.lyon@linaro.org> wrote: >>> What do people think about this? >> >> Seems reasonable. > > Thanks, committed as r268511. There are a few improvements we might want to look at; 1) application to the libraries (other than libstdc++) 2) things are inconsistent between -j1 and -jN check runs because the dg-extract doesn’t seem to be run for j1. - this means that the timeout warnings are not changed - but it also seems to remove the sorting (for some reason I thought that was part of test_summary), which means that one can’t compare a -j1 run with a -jN run easily (or so it seems from some quick tests). .. won’t have any cycles for looking at this in the next few weeks - but a “heads up” anyway. Iain
Hi Christophe, > dg-extract-results currently moves lines like > WARNING: program timed out > at the end of each .exp section when it generates .sum files. > > This is because it sorts its output based on the 2nd field, which is > normally the testname as in: > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test > > As you can notice 'program' comes after > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > most (all?) GCC testnames. > > This is a bit of a pain when trying to handle transient test failures > because you can no longer match such a WARNING line to its FAIL > counterpart. > > The attached patch changes this behavior by replacing the line > WARNING: program timed out > with > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test program > timed out > > The effect is that this line will now appear immediately above the > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test > so that it's easier to match them. > > > I'm not sure how much people depend on the .sum format, I also > considered emitting > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > -flto -fno-use-linker-plugin -flto-partition=none execution test > > I also restricted the patch to handling only 'program timed out' > cases, to avoid breaking other things. > > I considered fixing this in Dejagnu, but it seemed more complicated, > and would delay adoption in GCC anyway. > > What do people think about this? I just had a case where your patch broke the generation of go.sum. This is on Solaris 11.5 with python 2.7.15: ro@colima 68 > /bin/ksh /vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.sh testsuite/go*/*.sum.sep > testsuite/go/go.sum Traceback (most recent call last): File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 605, in <module> Prog().main() File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 569, in main self.parse_file (filename, file) File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 427, in parse_file num_variations) File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 311, in parse_run first_key = key UnboundLocalError: local variable 'key' referenced before assignment Before your patch, key cannot have been undefined, now it is. I've verified this by removing the WARNING: lines from the two affected go.sum.sep files and now go.sum creation just works fine. Rainer -- ----------------------------------------------------------------------------- Rainer Orth, Center for Biotechnology, Bielefeld University
On Mon, 18 Feb 2019 at 21:12, Rainer Orth <ro@cebitec.uni-bielefeld.de> wrote: > > Hi Christophe, > > > dg-extract-results currently moves lines like > > WARNING: program timed out > > at the end of each .exp section when it generates .sum files. > > > > This is because it sorts its output based on the 2nd field, which is > > normally the testname as in: > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test > > > > As you can notice 'program' comes after > > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > > most (all?) GCC testnames. > > > > This is a bit of a pain when trying to handle transient test failures > > because you can no longer match such a WARNING line to its FAIL > > counterpart. > > > > The attached patch changes this behavior by replacing the line > > WARNING: program timed out > > with > > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test program > > timed out > > > > The effect is that this line will now appear immediately above the > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test > > so that it's easier to match them. > > > > > > I'm not sure how much people depend on the .sum format, I also > > considered emitting > > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > > -flto -fno-use-linker-plugin -flto-partition=none execution test > > > > I also restricted the patch to handling only 'program timed out' > > cases, to avoid breaking other things. > > > > I considered fixing this in Dejagnu, but it seemed more complicated, > > and would delay adoption in GCC anyway. > > > > What do people think about this? > > I just had a case where your patch broke the generation of go.sum. > This is on Solaris 11.5 with python 2.7.15: > > ro@colima 68 > /bin/ksh /vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.sh testsuite/go*/*.sum.sep > testsuite/go/go.sum > Traceback (most recent call last): > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 605, in <module> > Prog().main() > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 569, in main > self.parse_file (filename, file) > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 427, in parse_file > num_variations) > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 311, in parse_run > first_key = key > UnboundLocalError: local variable 'key' referenced before assignment > > Before your patch, key cannot have been undefined, now it is. I've > verified this by removing the WARNING: lines from the two affected > go.sum.sep files and now go.sum creation just works fine. > Sorry for the breakage. Can you send me the .sum that cause the problem so that I can reproduce it? Thanks Christophe > Rainer > > -- > ----------------------------------------------------------------------------- > Rainer Orth, Center for Biotechnology, Bielefeld University
On Tue, 19 Feb 2019 at 10:28, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > On Mon, 18 Feb 2019 at 21:12, Rainer Orth <ro@cebitec.uni-bielefeld.de> wrote: > > > > Hi Christophe, > > > > > dg-extract-results currently moves lines like > > > WARNING: program timed out > > > at the end of each .exp section when it generates .sum files. > > > > > > This is because it sorts its output based on the 2nd field, which is > > > normally the testname as in: > > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > > -fno-use-linker-plugin -flto-partition=none execution test > > > > > > As you can notice 'program' comes after > > > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > > > most (all?) GCC testnames. > > > > > > This is a bit of a pain when trying to handle transient test failures > > > because you can no longer match such a WARNING line to its FAIL > > > counterpart. > > > > > > The attached patch changes this behavior by replacing the line > > > WARNING: program timed out > > > with > > > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > > > -fno-use-linker-plugin -flto-partition=none execution test program > > > timed out > > > > > > The effect is that this line will now appear immediately above the > > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > > -fno-use-linker-plugin -flto-partition=none execution test > > > so that it's easier to match them. > > > > > > > > > I'm not sure how much people depend on the .sum format, I also > > > considered emitting > > > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > > > -flto -fno-use-linker-plugin -flto-partition=none execution test > > > > > > I also restricted the patch to handling only 'program timed out' > > > cases, to avoid breaking other things. > > > > > > I considered fixing this in Dejagnu, but it seemed more complicated, > > > and would delay adoption in GCC anyway. > > > > > > What do people think about this? > > > > I just had a case where your patch broke the generation of go.sum. > > This is on Solaris 11.5 with python 2.7.15: > > > > ro@colima 68 > /bin/ksh /vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.sh testsuite/go*/*.sum.sep > testsuite/go/go.sum > > Traceback (most recent call last): > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 605, in <module> > > Prog().main() > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 569, in main > > self.parse_file (filename, file) > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 427, in parse_file > > num_variations) > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 311, in parse_run > > first_key = key > > UnboundLocalError: local variable 'key' referenced before assignment > > > > Before your patch, key cannot have been undefined, now it is. I've > > verified this by removing the WARNING: lines from the two affected > > go.sum.sep files and now go.sum creation just works fine. > > > > Sorry for the breakage. > > Can you send me the .sum that cause the problem so that I can reproduce it? > So the problem happens when a WARNING is the first result of a new harness. This is fixed by the attached dg-extract-results.patch2.txt. While looking at it, I noticed that the ordering wasn't right with the shell version, though I did test it before sending the previous patch. The attached dg-extract-results.patch1.txt makes sure the WARNING: line appears before the following testcase with the shell version too. Are both OK? Christophe > Thanks > > Christophe > > > Rainer > > > > -- > > ----------------------------------------------------------------------------- > > Rainer Orth, Center for Biotechnology, Bielefeld University 2019-02-19 Christophe Lyon <christophe.lyon@linaro.org> contrib/ * dg-extract-results.sh: Fix order of WARNING and following test result. diff --git a/contrib/dg-extract-results.sh b/contrib/dg-extract-results.sh index e9833c1..86c4246 100755 --- a/contrib/dg-extract-results.sh +++ b/contrib/dg-extract-results.sh @@ -350,6 +350,7 @@ BEGIN { if (timeout_cnt != 0) { printf "%s %08d|%s program timed out.\n", testname, timeout_cnt, timeout_msg >> curfile timeout_cnt = 0 + cnt = cnt + 1 } printf "%s %08d|", testname, cnt >> curfile cnt = cnt + 1 2019-02-19 Christophe Lyon <christophe.lyon@linaro.org> contrib/ * dg-extract-results.py: Handle case where a WARNING happens with the first test of a harness. diff --git a/contrib/dg-extract-results.py b/contrib/dg-extract-results.py index ed62f73..5bf2f87 100644 --- a/contrib/dg-extract-results.py +++ b/contrib/dg-extract-results.py @@ -307,8 +307,8 @@ class Prog: has_warning = 0 key = (name, len (harness.results)) harness.results.append ((key, line)) - if not first_key and sort_logs: - first_key = key + if not first_key and sort_logs: + first_key = key if line.startswith ('ERROR: (DejaGnu)'): for i in range (len (self.count_names)): if 'DejaGnu errors' in self.count_names[i]:
On Tue, 19 Feb 2019 at 11:29, Christophe Lyon <christophe.lyon@linaro.org> wrote: > > On Tue, 19 Feb 2019 at 10:28, Christophe Lyon > <christophe.lyon@linaro.org> wrote: > > > > On Mon, 18 Feb 2019 at 21:12, Rainer Orth <ro@cebitec.uni-bielefeld.de> wrote: > > > > > > Hi Christophe, > > > > > > > dg-extract-results currently moves lines like > > > > WARNING: program timed out > > > > at the end of each .exp section when it generates .sum files. > > > > > > > > This is because it sorts its output based on the 2nd field, which is > > > > normally the testname as in: > > > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > > > -fno-use-linker-plugin -flto-partition=none execution test > > > > > > > > As you can notice 'program' comes after > > > > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > > > > most (all?) GCC testnames. > > > > > > > > This is a bit of a pain when trying to handle transient test failures > > > > because you can no longer match such a WARNING line to its FAIL > > > > counterpart. > > > > > > > > The attached patch changes this behavior by replacing the line > > > > WARNING: program timed out > > > > with > > > > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > > > > -fno-use-linker-plugin -flto-partition=none execution test program > > > > timed out > > > > > > > > The effect is that this line will now appear immediately above the > > > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > > > -fno-use-linker-plugin -flto-partition=none execution test > > > > so that it's easier to match them. > > > > > > > > > > > > I'm not sure how much people depend on the .sum format, I also > > > > considered emitting > > > > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > > > > -flto -fno-use-linker-plugin -flto-partition=none execution test > > > > > > > > I also restricted the patch to handling only 'program timed out' > > > > cases, to avoid breaking other things. > > > > > > > > I considered fixing this in Dejagnu, but it seemed more complicated, > > > > and would delay adoption in GCC anyway. > > > > > > > > What do people think about this? > > > > > > I just had a case where your patch broke the generation of go.sum. > > > This is on Solaris 11.5 with python 2.7.15: > > > > > > ro@colima 68 > /bin/ksh /vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.sh testsuite/go*/*.sum.sep > testsuite/go/go.sum > > > Traceback (most recent call last): > > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 605, in <module> > > > Prog().main() > > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 569, in main > > > self.parse_file (filename, file) > > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 427, in parse_file > > > num_variations) > > > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 311, in parse_run > > > first_key = key > > > UnboundLocalError: local variable 'key' referenced before assignment > > > > > > Before your patch, key cannot have been undefined, now it is. I've > > > verified this by removing the WARNING: lines from the two affected > > > go.sum.sep files and now go.sum creation just works fine. > > > > > > > Sorry for the breakage. > > > > Can you send me the .sum that cause the problem so that I can reproduce it? > > > > So the problem happens when a WARNING is the first result of a new harness. > This is fixed by the attached dg-extract-results.patch2.txt. > > While looking at it, I noticed that the ordering wasn't right with the > shell version, > though I did test it before sending the previous patch. > The attached dg-extract-results.patch1.txt makes sure the WARNING: line > appears before the following testcase with the shell version too. > > Are both OK? > Ping? > Christophe > > > > Thanks > > > > Christophe > > > > > Rainer > > > > > > -- > > > ----------------------------------------------------------------------------- > > > Rainer Orth, Center for Biotechnology, Bielefeld University
Hi Christophe, > On Tue, 19 Feb 2019 at 10:28, Christophe Lyon > <christophe.lyon@linaro.org> wrote: >> >> On Mon, 18 Feb 2019 at 21:12, Rainer Orth <ro@cebitec.uni-bielefeld.de> wrote: >> > >> > Hi Christophe, >> > >> > > dg-extract-results currently moves lines like >> > > WARNING: program timed out >> > > at the end of each .exp section when it generates .sum files. >> > > >> > > This is because it sorts its output based on the 2nd field, which is >> > > normally the testname as in: >> > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto >> > > -fno-use-linker-plugin -flto-partition=none execution test >> > > >> > > As you can notice 'program' comes after >> > > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after >> > > most (all?) GCC testnames. >> > > >> > > This is a bit of a pain when trying to handle transient test failures >> > > because you can no longer match such a WARNING line to its FAIL >> > > counterpart. >> > > >> > > The attached patch changes this behavior by replacing the line >> > > WARNING: program timed out >> > > with >> > > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto >> > > -fno-use-linker-plugin -flto-partition=none execution test program >> > > timed out >> > > >> > > The effect is that this line will now appear immediately above the >> > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto >> > > -fno-use-linker-plugin -flto-partition=none execution test >> > > so that it's easier to match them. >> > > >> > > >> > > I'm not sure how much people depend on the .sum format, I also >> > > considered emitting >> > > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 >> > > -flto -fno-use-linker-plugin -flto-partition=none execution test >> > > >> > > I also restricted the patch to handling only 'program timed out' >> > > cases, to avoid breaking other things. >> > > >> > > I considered fixing this in Dejagnu, but it seemed more complicated, >> > > and would delay adoption in GCC anyway. >> > > >> > > What do people think about this? >> > >> > I just had a case where your patch broke the generation of go.sum. >> > This is on Solaris 11.5 with python 2.7.15: >> > >> > ro@colima 68 > /bin/ksh /vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.sh testsuite/go*/*.sum.sep > testsuite/go/go.sum >> > Traceback (most recent call last): >> > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 605, in <module> >> > Prog().main() >> > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 569, in main >> > self.parse_file (filename, file) >> > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 427, in parse_file >> > num_variations) >> > File "/vol/gcc/src/hg/trunk/local/gcc/../contrib/dg-extract-results.py", line 311, in parse_run >> > first_key = key >> > UnboundLocalError: local variable 'key' referenced before assignment >> > >> > Before your patch, key cannot have been undefined, now it is. I've >> > verified this by removing the WARNING: lines from the two affected >> > go.sum.sep files and now go.sum creation just works fine. >> > >> >> Sorry for the breakage. >> >> Can you send me the .sum that cause the problem so that I can reproduce it? >> > > So the problem happens when a WARNING is the first result of a new harness. > This is fixed by the attached dg-extract-results.patch2.txt. > > While looking at it, I noticed that the ordering wasn't right with the > shell version, > though I did test it before sending the previous patch. > The attached dg-extract-results.patch1.txt makes sure the WARNING: line > appears before the following testcase with the shell version too. > > Are both OK? ok for now to avoid silently losing considerable parts of the test results. However, I've lots of problems with the current approach which I'll detail in a separate reply to your original test submissions. Rainer -- ----------------------------------------------------------------------------- Rainer Orth, Center for Biotechnology, Bielefeld University
Hi Christophe, I know I'm coming quite late to this, but I've got quite a number of problems with your approach. > dg-extract-results currently moves lines like > WARNING: program timed out > at the end of each .exp section when it generates .sum files. This is only true when dg-extract-results.py is used. When it is disabled or no python present and thus the shell version is used, this issues doesn't exist. There are other even more severe issues with how the python version sorts lines, as has been observed in the gdb community: https://sourceware.org/ml/gdb-patches/2018-10/msg00007.html Even when passing just a single .sum files to dg-extract-results.py, the order changes. > This is because it sorts its output based on the 2nd field, which is > normally the testname as in: > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test > > As you can notice 'program' comes after > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > most (all?) GCC testnames. > > This is a bit of a pain when trying to handle transient test failures > because you can no longer match such a WARNING line to its FAIL > counterpart. > > The attached patch changes this behavior by replacing the line > WARNING: program timed out > with > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test program > timed out > > The effect is that this line will now appear immediately above the > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > -fno-use-linker-plugin -flto-partition=none execution test > so that it's easier to match them. > > > I'm not sure how much people depend on the .sum format, I also > considered emitting > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > -flto -fno-use-linker-plugin -flto-partition=none execution test > > I also restricted the patch to handling only 'program timed out' > cases, to avoid breaking other things. > > I considered fixing this in Dejagnu, but it seemed more complicated, > and would delay adoption in GCC anyway. I fear this is the wrong approach: DejaGnu owns the .sum format and they need to be involved in extensions. Besides, it should be possible to satisfy the need to have this approved and incorporated upstream and not having to wait for a long time until gcc can use it: AFAICS it should be possible to wrap DejaGnu's warning proc in a gcc-local version that checks for the "program timed out" arg and extracts the test name from the caller that has it (dg-test) using uplevel. I've just not checked yet if the call depth from dg-test to warning is constant in the case we care about. > What do people think about this? I've more problems with your approach: * When done in dg-extrace-results.sh/py, it only works for parallel tests. Both sequential tests (like libgomp and several others) and sequential builds don't get the additional information. Having to filter every single .sum/.log file through dg-e-r seems totally wasteful to me. * Right now, your patch fabricates misleading timeout information, e.g. I've seen WARNING: g++.dg/cpp0x/enum32.C -std=c++14 (test for errors, line 24) program timed out. where the original g++.sum file has WARNING: program timed out PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for errors, line 24) PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for excess errors) and the original g++.log /vol/gcc/src/hg/trunk/local/gcc/testsuite/g++.dg/cpp0x/enum32.C: In function 'int main()': /vol/gcc/src/hg/trunk/local/gcc/testsuite/g++.dg/cpp0x/enum32.C:24:7: error: 'C::D C::y' is private within this context /vol/gcc/src/hg/trunk/local/gcc/testsuite/g++.dg/cpp0x/enum32.C:19:4: note: declared private here WARNING: program timed out compiler exited with status 1 PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for errors, line 24) PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for excess errors) The only two places where DejaGnu can emit the "program timed out" message is for either the compilation timing out or exection timeouts. So the only messages that make sense would pertain to those, not stuff about other tests. I think those issues warrant persueing the alternative approach I've lined out above. Rainer -- ----------------------------------------------------------------------------- Rainer Orth, Center for Biotechnology, Bielefeld University
On Tue, 5 Mar 2019 at 16:17, Rainer Orth <ro@cebitec.uni-bielefeld.de> wrote: > > Hi Christophe, > > I know I'm coming quite late to this, but I've got quite a number of > problems with your approach. Thanks for your feedback > > dg-extract-results currently moves lines like > > WARNING: program timed out > > at the end of each .exp section when it generates .sum files. > > This is only true when dg-extract-results.py is used. When it is > disabled or no python present and thus the shell version is used, this > issues doesn't exist. There are other even more severe issues with how The machines I used all have python, I had to hack the .sh version to avoid using the python one to make sure I applied the same changes to both. However, the .sh version does call 'sort' in some cases. If you feed it with an input like: Running my.exp ... PASS: test1 WARNING: program timed out PASS: test2 Running my.exp ... PASS: test3 WARNING: program timed out PASS: test4 (that is, twice the same .exp), the output is: * before my patch: Running my.exp ... WARNING: program timed out WARNING: program timed out PASS: test1 PASS: test2 PASS: test3 PASS: test4 * after my patch: Running my.exp ... PASS: test1 PASS: test2 WARNING: test2 program timed out. PASS: test3 PASS: test4 WARNING: test4 program timed out. > the python version sorts lines, as has been observed in the gdb > community: > > https://sourceware.org/ml/gdb-patches/2018-10/msg00007.html > > Even when passing just a single .sum files to dg-extract-results.py, the > order changes. > I tested only with gcc results, for which there might not be the same problem (the tests are run in alphabetical order within one .exp file). Do you know why results are sorted in the first place? > > This is because it sorts its output based on the 2nd field, which is > > normally the testname as in: > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test > > > > As you can notice 'program' comes after > > gcc.c-torture/execute/20020129-1.c alphabetically, and generally after > > most (all?) GCC testnames. > > > > This is a bit of a pain when trying to handle transient test failures > > because you can no longer match such a WARNING line to its FAIL > > counterpart. > > > > The attached patch changes this behavior by replacing the line > > WARNING: program timed out > > with > > WARNING: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test program > > timed out > > > > The effect is that this line will now appear immediately above the > > FAIL: gcc.c-torture/execute/20020129-1.c -O2 -flto > > -fno-use-linker-plugin -flto-partition=none execution test > > so that it's easier to match them. > > > > > > I'm not sure how much people depend on the .sum format, I also > > considered emitting > > WARNING: program timed out gcc.c-torture/execute/20020129-1.c -O2 > > -flto -fno-use-linker-plugin -flto-partition=none execution test > > > > I also restricted the patch to handling only 'program timed out' > > cases, to avoid breaking other things. > > > > I considered fixing this in Dejagnu, but it seemed more complicated, > > and would delay adoption in GCC anyway. > > I fear this is the wrong approach: DejaGnu owns the .sum format and they > need to be involved in extensions. Besides, it should be possible to > satisfy the need to have this approved and incorporated upstream and not > having to wait for a long time until gcc can use it: AFAICS it should be > possible to wrap DejaGnu's warning proc in a gcc-local version that > checks for the "program timed out" arg and extracts the test name from > the caller that has it (dg-test) using uplevel. I've just not checked > yet if the call depth from dg-test to warning is constant in the case we > care about. I looked at that some time ago, but never managed to find a solution that I thought would be easily acceptable. I feared that some people/scripts depend on the actual message format and was reluctant to do that. But your proposal sounds reasonable. As you say, changing DejaGnu means it will take time to have the patch widely used. Changing gcc-local harness can break other scripts, hence I thought it was safer to change the consumer of .sum files. > > What do people think about this? > > I've more problems with your approach: > > * When done in dg-extrace-results.sh/py, it only works for parallel > tests. Both sequential tests (like libgomp and several others) and > sequential builds don't get the additional information. Having to > filter every single .sum/.log file through dg-e-r seems totally > wasteful to me. Sorry, in our testing we focus on c/c++/fortran so I missed the others. However, my understanding of your comments is that sequential builds do not suffer from this ordering problem? > * Right now, your patch fabricates misleading timeout information, > e.g. I've seen > > WARNING: g++.dg/cpp0x/enum32.C -std=c++14 (test for errors, line 24) program timed out. > > where the original g++.sum file has > > WARNING: program timed out > PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for errors, line 24) > PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for excess errors) > > and the original g++.log > > /vol/gcc/src/hg/trunk/local/gcc/testsuite/g++.dg/cpp0x/enum32.C: In function 'int main()': > /vol/gcc/src/hg/trunk/local/gcc/testsuite/g++.dg/cpp0x/enum32.C:24:7: error: 'C::D C::y' is private within this context > /vol/gcc/src/hg/trunk/local/gcc/testsuite/g++.dg/cpp0x/enum32.C:19:4: note: declared private here > WARNING: program timed out > compiler exited with status 1 > PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for errors, line 24) > PASS: g++.dg/cpp0x/enum32.C -std=c++14 (test for excess errors) > > The only two places where DejaGnu can emit the "program timed out" > message is for either the compilation timing out or exection timeouts. > So the only messages that make sense would pertain to those, not stuff > about other tests. > Looks like I didn't anticipate that WARNING could be followed by PASS... Isn't that test failing?? > I think those issues warrant persueing the alternative approach I've > lined out above. Yes. I'll commit my update (in my previous mail), and I can revert both when you come up with a fix using your alternative approach. Thanks Christophe > > Rainer > > -- > ----------------------------------------------------------------------------- > Rainer Orth, Center for Biotechnology, Bielefeld University
diff --git a/contrib/dg-extract-results.py b/contrib/dg-extract-results.py index 4b02a5b..ed62f73 100644 --- a/contrib/dg-extract-results.py +++ b/contrib/dg-extract-results.py @@ -239,6 +239,7 @@ class Prog: harness = None segment = None final_using = 0 + has_warning = 0 # If this is the first run for this variation, add any text before # the first harness to the header. @@ -292,8 +293,20 @@ class Prog: # Ugly hack to get the right order for gfortran. if name.startswith ('gfortran.dg/g77/'): name = 'h' + name - key = (name, len (harness.results)) - harness.results.append ((key, line)) + # If we have a time out warning, make sure it appears + # before the following testcase diagnostic: we insert + # the testname before 'program' so that sort faces a + # list of testhanes. + if line.startswith ('WARNING: program timed out'): + has_warning = 1 + else: + if has_warning == 1: + key = (name, len (harness.results)) + myline = 'WARNING: %s program timed out.\n' % name + harness.results.append ((key, myline)) + has_warning = 0 + key = (name, len (harness.results)) + harness.results.append ((key, line)) if not first_key and sort_logs: first_key = key if line.startswith ('ERROR: (DejaGnu)'): diff --git a/contrib/dg-extract-results.sh b/contrib/dg-extract-results.sh index 6ee3d26..e9833c1 100755 --- a/contrib/dg-extract-results.sh +++ b/contrib/dg-extract-results.sh @@ -298,6 +298,8 @@ BEGIN { cnt=0 print_using=0 need_close=0 + has_timeout=0 + timeout_cnt=0 } /^EXPFILE: / { expfiles[expfileno] = \$2 @@ -329,16 +331,36 @@ BEGIN { # Ugly hack for gfortran.dg/dg.exp if ("$TOOL" == "gfortran" && testname ~ /^gfortran.dg\/g77\//) testname="h"testname + if (\$1 == "WARNING:" && \$2 == "program" && \$3 == "timed" && (\$4 == "out" || \$4 == "out.")) { + has_timeout=1 + timeout_cnt=cnt + } else { + # Prepare timeout replacement message in case it's needed + timeout_msg=\$0 + sub(\$1, "WARNING:", timeout_msg) + } } /^$/ { if ("$MODE" == "sum") next } { if (variant == curvar && curfile) { if ("$MODE" == "sum") { - printf "%s %08d|", testname, cnt >> curfile - cnt = cnt + 1 + # Do not print anything if the current line is a timeout + if (has_timeout == 0) { + # If the previous line was a timeout, + # insert the full current message without keyword + if (timeout_cnt != 0) { + printf "%s %08d|%s program timed out.\n", testname, timeout_cnt, timeout_msg >> curfile + timeout_cnt = 0 + } + printf "%s %08d|", testname, cnt >> curfile + cnt = cnt + 1 + filewritten[curfile]=1 + need_close=1 + if (timeout_cnt == 0) + print >> curfile + } + + has_timeout=0 } - filewritten[curfile]=1 - need_close=1 - print >> curfile } else next }