Strace
Phyx
lonetiger at gmail.com
Mon Jun 18 19:32:07 UTC 2018
Hi Simon,
T11244 and the plugin output changes have been done after my commit to fix
the tests, hence the new std issues. Those have to be fixed up again...
I'm curious about the threading issues though.
One way to find out is by running the entire testsuite with -j again but
with VERBOSE=3 and piping to a file.
This will show the underlying tool's output instead of throwing it away.
This will of course generate lots of data
but shouldn't be at the level of the strace output, but should give an
indication of what's going on.
Cheers,
Tamar
On Mon, Jun 18, 2018, 11:44 Simon Peyton Jones <simonpj at microsoft.com>
wrote:
> Tamar
>
>
>
> OK, the first thing I tried was this
>
> - cd testsuite/tests/plugins
> - make
>
> Note no “-j”, so this is single threaded.
>
>
>
> Output is below. Yes, fewer failures, so it does seem that many of the
> failures I see in a generic test suite run are to do with concurrency. So
> that’s Bug #1.
>
>
>
> But even if Bug #1 was solved, I seem to get three failures that happen
> even in the absence of concurrent testing. This is Bug #2 (or maybe 2,3,4).
>
>
>
> Happy to run more commands!
>
>
>
> Simon
>
>
>
> *.../tests/plugins$ make*
>
> *PYTHON="python3" "python3" ../../driver/runtests.py -e
> "ghc_compiler_always_flags='-dcore-lint -dcmm-lint -no-user-package-db
> -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups
> -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output'"
> -e config.compiler_debugged=False -e ghc_with_native_codegen=1 -e
> config.have_vanilla=True -e config.have_dynamic=False -e
> config.have_profiling=False -e ghc_with_threaded_rts=1 -e
> ghc_with_dynamic_rts=0 -e config.have_interp=True -e
> config.unregisterised=False -e config.have_gdb=False -e
> config.have_readelf=True -e config.ghc_dynamic_by_default=False -e
> config.ghc_dynamic=False -e ghc_with_smp=1 -e ghc_with_llvm=0 -e
> windows=True -e darwin=False -e config.in_tree_compiler=True -e
> config.cleanup=True -e config.local=True --rootdir=.
> --config-file=../../config/ghc -e 'config.confdir="../../config"' -e
> 'config.platform="x86_64-unknown-mingw32"' -e 'config.os="mingw32"' -e
> 'config.arch="x86_64"' -e 'config.wordsize="64"' -e 'config.timeout=int()
> or config.timeout' -e 'config.exeext=".exe"' -e
> 'config.top="/c/code/HEAD/testsuite"' --config
> 'compiler="/c/code/HEAD/inplace/bin/ghc-stage2.exe"' --config
> 'ghc_pkg="/c/code/HEAD/inplace/bin/ghc-pkg.exe"' --config 'haddock='
> --config 'hp2ps="/c/code/HEAD/inplace/bin/hp2ps.exe"' --config
> 'hpc="/c/code/HEAD/inplace/bin/hpc.exe"' --config 'gs="gs"' --config
> 'timeout_prog="../../timeout/install-inplace/bin/timeout.exe"' -e
> "config.stage=2" \*
>
> * \*
>
> * \*
>
> * \*
>
> * \*
>
> * \*
>
> * \*
>
>
>
> *Timeout is 300*
>
> *Found 1 .T files...*
>
> *Beginning test run at Mon Jun 18 11:24:57 2018 GMTST*
>
> *--- ./plugins09.run/plugins09.stdout.normalised 2018-06-18
> 11:27:47.971987800 +0100*
>
> *+++ ./plugins09.run/plugins09.run.stdout.normalised 2018-06-18
> 11:27:47.972177400 +0100*
>
> *@@ -1,9 +0,0 @@*
>
> *-parsePlugin(a,b)*
>
> *-interfacePlugin: Prelude*
>
> *-interfacePlugin: GHC.Float*
>
> *-interfacePlugin: GHC.Base*
>
> *-interfacePlugin: GHC.Types*
>
> *-typeCheckPlugin (rn)*
>
> *-typeCheckPlugin (tc)*
>
> *-interfacePlugin: GHC.Integer.Type*
>
> *-interfacePlugin: GHC.Natural*
>
> *--- ./plugins11.run/plugins11.stdout.normalised 2018-06-18
> 11:28:40.307222400 +0100*
>
> *+++ ./plugins11.run/plugins11.run.stdout.normalised 2018-06-18
> 11:28:40.307675400 +0100*
>
> *@@ -1,9 +0,0 @@*
>
> *-parsePlugin()*
>
> *-interfacePlugin: Prelude*
>
> *-interfacePlugin: GHC.Float*
>
> *-interfacePlugin: GHC.Base*
>
> *-interfacePlugin: GHC.Types*
>
> *-typeCheckPlugin (rn)*
>
> *-typeCheckPlugin (tc)*
>
> *-interfacePlugin: GHC.Integer.Type*
>
> *-interfacePlugin: GHC.Natural*
>
> *--- ./T11244.run/T11244.stderr.normalised 2018-06-18
> 11:32:21.142334600 +0100*
>
> *+++ ./T11244.run/T11244.run.stderr.normalised 2018-06-18
> 11:32:21.145148100 +0100*
>
> *@@ -1,4 +1,4 @@*
>
> *-<command line>: Could not load module ‘RuleDefiningPlugin’*
>
> *+<command line>: Could not find module ‘RuleDefiningPlugin’*
>
> *It is a member of the hidden package ‘rule-defining-plugin-0.1’.*
>
> *You can run ‘:set -package rule-defining-plugin’ to expose it.*
>
> *(Note: this unloads all the modules in the current scope.)*
>
> *====> Scanning ./all.T*
>
> *=====> plugins01(normal) 1 of 25 [0, 0, 0]*
>
> *cd "./plugins01.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins01 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins01.run" && $MAKE -s --no-print-directory plugins01 *
>
> *=====> plugins02(normal) 2 of 25 [0, 0, 0]*
>
> *cd "./plugins02.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins02 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins02.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" -c
> plugins02.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts
> -fno-warn-missed-specialisations -fshow-warning-groups
> -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output
> -package-db simple-plugin/pkg.plugins02/local.package.conf -fplugin
> Simple.BadlyTypedPlugin -package simple-plugin -static*
>
> *=====> plugins03(normal) 3 of 25 [0, 0, 0]*
>
> *cd "./plugins03.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins03 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins03.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" -c
> plugins03.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts
> -fno-warn-missed-specialisations -fshow-warning-groups
> -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output
> -package-db simple-plugin/pkg.plugins03/local.package.conf -fplugin
> Simple.NonExistentPlugin -package simple-plugin*
>
> *=====> plugins04(normal) 4 of 25 [0, 0, 0]*
>
> *cd "./plugins04.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe"
> --make plugins04 -dcore-lint -dcmm-lint -no-user-package-db -rtsopts
> -fno-warn-missed-specialisations -fshow-warning-groups
> -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output
> -package ghc -fplugin HomePackagePlugin*
>
> *=====> plugins05(normal) 5 of 25 [0, 0, 0]*
>
> *cd "./plugins05.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" --make
> -o plugins05 plugins05 -dcore-lint -dcmm-lint -no-user-package-db -rtsopts
> -fno-warn-missed-specialisations -fshow-warning-groups
> -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output
> -package ghc*
>
> *cd "./plugins05.run" && ./plugins05 *
>
> *=====> plugins07(normal) 7 of 25 [0, 0, 0]*
>
> *cd "./plugins07.run" && $MAKE -s --no-print-directory -C
> rule-defining-plugin package.plugins07 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins07.run" && $MAKE -s --no-print-directory plugins07 *
>
> *=====> plugins08(normal) 8 of 25 [0, 0, 0]*
>
> *cd "./plugins08.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins08 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins08.run" && $MAKE -s --no-print-directory plugins08 *
>
> *=====> plugins09(normal) 9 of 25 [0, 0, 0]*
>
> *cd "./plugins09.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins09 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins09.run" && $MAKE -s --no-print-directory plugins09 *
>
> *Actual stdout output differs from expected:*
>
> *diff -uw "./plugins09.run/plugins09.stdout.normalised"
> "./plugins09.run/plugins09.run.stdout.normalised"*
>
> **** unexpected failure for plugins09(normal)*
>
> *=====> plugins10(normal) 10 of 25 [0, 1, 0]*
>
> *cd "./plugins10.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins10 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins10.run" && $MAKE -s --no-print-directory plugins10 *
>
> *=====> plugins11(normal) 11 of 25 [0, 1, 0]*
>
> *cd "./plugins11.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins11 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins11.run" && $MAKE -s --no-print-directory plugins11 *
>
> *Actual stdout output differs from expected:*
>
> *diff -uw "./plugins11.run/plugins11.stdout.normalised"
> "./plugins11.run/plugins11.run.stdout.normalised"*
>
> **** unexpected failure for plugins11(normal)*
>
> *=====> plugins12(normal) 12 of 25 [0, 2, 0]*
>
> *cd "./plugins12.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins12 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins12.run" && $MAKE -s --no-print-directory plugins12 *
>
> *=====> plugins13(normal) 13 of 25 [0, 2, 0]*
>
> *cd "./plugins13.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins13 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins13.run" && $MAKE -s --no-print-directory plugins13 *
>
> *=====> plugins14(normal) 14 of 25 [0, 2, 0]*
>
> *cd "./plugins14.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins14 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins14.run" && $MAKE -s --no-print-directory plugins14 *
>
> *=====> plugins15(normal) 15 of 25 [0, 2, 0]*
>
> *cd "./plugins15.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins15 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugins15.run" && $MAKE -s --no-print-directory plugins15 *
>
> *=====> T10420(normal) 16 of 25 [0, 2, 0]*
>
> *cd "./T10420.run" && $MAKE -s --no-print-directory -C
> rule-defining-plugin package.T10420 TOP=/c/code/HEAD/testsuite*
>
> *cd "./T10420.run" && $MAKE -s --no-print-directory T10420 *
>
> *=====> T10294(normal) 17 of 25 [0, 2, 0]*
>
> *cd "./T10294.run" && $MAKE -s --no-print-directory -C annotation-plugin
> package.T10294 TOP=/c/code/HEAD/testsuite*
>
> *cd "./T10294.run" && $MAKE -s --no-print-directory T10294 *
>
> *=====> T10294a(normal) 18 of 25 [0, 2, 0]*
>
> *cd "./T10294a.run" && $MAKE -s --no-print-directory -C annotation-plugin
> package.T10294a TOP=/c/code/HEAD/testsuite*
>
> *cd "./T10294a.run" && $MAKE -s --no-print-directory T10294a *
>
> *=====> frontend01(normal) 19 of 25 [0, 2, 0]*
>
> *cd "./frontend01.run" && $MAKE -s --no-print-directory frontend01 *
>
> *=====> T11244(normal) 20 of 25 [0, 2, 0]*
>
> *cd "./T11244.run" && $MAKE -s --no-print-directory -C
> rule-defining-plugin package.T11244 TOP=/c/code/HEAD/testsuite*
>
> *cd "./T11244.run" && $MAKE -s --no-print-directory T11244 *
>
> *Actual stderr output differs from expected:*
>
> *diff -uw "./T11244.run/T11244.stderr.normalised"
> "./T11244.run/T11244.run.stderr.normalised"*
>
> **** unexpected failure for T11244(normal)*
>
> *=====> T12567a(normal) 21 of 25 [0, 3, 0]*
>
> *cd "./T12567a.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.T12567a TOP=/c/code/HEAD/testsuite*
>
> *cd "./T12567a.run" && $MAKE -s --no-print-directory T12567a *
>
> *=====> T14335(normal) 22 of 25 [0, 3, 0]*
>
> *cd "./T14335.run" && $MAKE -s --no-print-directory -C simple-plugin
> package.plugins01 TOP=/c/code/HEAD/testsuite*
>
> *cd "./T14335.run" && "/c/code/HEAD/inplace/bin/ghc-stage2.exe" -c
> T14335.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts
> -fno-warn-missed-specialisations -fshow-warning-groups
> -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output
> -package-db simple-plugin/pkg.plugins01/local.package.conf -fplugin
> Simple.Plugin -fexternal-interpreter -package simple-plugin -static*
>
> *=====> plugin-recomp-pure(normal) 23 of 25 [0, 3, 0]*
>
> *cd "./plugin-recomp-pure.run" && $MAKE -s --no-print-directory -C
> plugin-recomp package.plugins01 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugin-recomp-pure.run" && $MAKE -s --no-print-directory
> plugin-recomp-pure *
>
> *=====> plugin-recomp-impure(normal) 24 of 25 [0, 3, 0]*
>
> *cd "./plugin-recomp-impure.run" && $MAKE -s --no-print-directory -C
> plugin-recomp package.plugins01 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugin-recomp-impure.run" && $MAKE -s --no-print-directory
> plugin-recomp-impure *
>
> *=====> plugin-recomp-flags(normal) 25 of 25 [0, 3, 0]*
>
> *cd "./plugin-recomp-flags.run" && $MAKE -s --no-print-directory -C
> plugin-recomp package.plugins01 TOP=/c/code/HEAD/testsuite*
>
> *cd "./plugin-recomp-flags.run" && $MAKE -s --no-print-directory
> plugin-recomp-flags *
>
>
>
> *Unexpected results from:*
>
> *TEST="T11244 plugins09 plugins11"*
>
>
>
> *SUMMARY for test run started at Mon Jun 18 11:24:57 2018 GMTST*
>
> *0:11:18 spent to go through*
>
> * 25 total tests, which gave rise to*
>
> * 35 test cases, of which*
>
> * 11 were skipped*
>
>
>
> * 0 had missing libraries*
>
> * 19 expected passes*
>
> * 2 expected failures*
>
>
>
> * 0 caused framework failures*
>
> * 0 caused framework warnings*
>
> * 0 unexpected passes*
>
> * 3 unexpected failures*
>
> * 0 unexpected stat failures*
>
>
>
> *Unexpected failures:*
>
> * plugins09.run plugins09 [bad stdout] (normal)*
>
> * plugins11.run plugins11 [bad stdout] (normal)*
>
> * T11244.run T11244 [bad stderr] (normal)*
>
>
>
> *make: *** [../../mk/test.mk:329 <http://test.mk:329>: test] Error 1*
>
> *.../tests/plugins$*
>
>
>
> *From:* Phyx <lonetiger at gmail.com>
> *Sent:* 13 June 2018 20:47
>
>
> *To:* Simon Peyton Jones <simonpj at microsoft.com>
> *Cc:* ghc-devs at haskell.org
> *Subject:* Re: Strace
>
>
>
>
>
> Hi Simon,
>
>
>
> On Wed, Jun 13, 2018 at 5:24 PM, Simon Peyton Jones <simonpj at microsoft.com>
> wrote:
>
> OK – so maybe the root cause is a framework failure – and indeed for the
> last few weeks I’ve seen
>
> Framework failures:
>
> plugins/plugins07.run plugins07 [normal] (pre_cmd failed: 2)
>
> plugins/T10420.run T10420 [normal] (pre_cmd failed: 2)
>
> plugins/T11244.run T11244 [normal] (pre_cmd failed: 2)
>
>
>
> I have just learned to live with these failures, because I knew you were
> working on making things better. But it sounds as if they are still taking
> place.
>
>
>
> The commit I made should have reduced the amount of failing tests to 0.
> framework failures are always quite unusual.
>
>
>
>
>
> So:
>
> - Yes, please make it not happen by default
>
> I've removed the code, if you update it should be gone. It was there and
> on by default because I was trying to debug failures on Harbormaster, I
>
> realized a switch isn't very useful as I won't be able to toggle it for
> Harbormaster anyway.
>
>
>
>
> -
> - If you don’t get these framework failures, can we work together to
> resolve them?
>
> These don't happen for me nor on Harbormaster, try picking a test, e.g
> T10420
>
>
>
> run only that test to make sure it's not a threading issue:
>
>
>
> make TEST=T10420 test -C testsuite/tests
>
>
>
> If it still gives a framework error then do at the top level
>
>
>
> make VERBOSE=3 TEST=T10420 test -C testsuite/tests
>
>
>
> once it runs, the output should contain the command it ran as a pre_cmd,
> and the stdout and
>
> stderr from the pre_cmd output. Could you then send the error?
>
>
>
> if it doesn't show any of this, try
>
>
>
> make CLEANP=0 VERBOSE=3 TEST= T10420 test -C testsuite/tests --trace
>
>
>
> and copy and paste the pre_cmd command, which should just replay the
> action it did.
>
>
>
>
>
> Cheers,
>
> Tamar
>
>
>
>
>
> Thanks
>
>
>
> Simon
>
>
>
> *From:* Phyx <lonetiger at gmail.com>
> *Sent:* 13 June 2018 17:19
> *To:* Simon Peyton Jones <simonpj at microsoft.com>
> *Cc:* ghc-devs at haskell.org
> *Subject:* Re: Strace
>
>
>
> Hi Simon,
>
>
>
> The strace is only supposed to run when the normal test pre_cmd fails.
>
> If it's running that often it means your tests are all failing during
> pre_cmd with a framework failure
>
> https://git.haskell.org/ghc.git/blobdiff/4778cba1dbb6adf495930322d7f9e9
> db0af60d8f..60fb2b2160aa16194b74262f4df8fad5af171b0f:/testsuite/driver/
> testlib.py
>
>
>
> But maybe I shouldn't turn this on my default. I'll pramaterize it when I
> get home.
>
>
>
> Tamar.
>
>
>
> On Wed, Jun 13, 2018, 17:09 Simon Peyton Jones <simonpj at microsoft.com>
> wrote:
>
> Tamar
>
> I’m getting *megabytes* of output from ‘sh validate’ on windows. It
> looks like this
>
> 629 151745 [main] sh 2880 fhandler_base::fhaccess: returning 0
>
> 291 152036 [main] sh 2880 faccessat: returning 0
>
> 7757 159793 [main] sh 2880 fhandler_base_overlapped::wait_overlapped:
> wfres 0, wores 1, bytes 7
>
> 179457 1608947 [main] make 11484 fhandler_base_overlapped::wait_overlapped:
> wfres 0, wores 1, bytes 7
>
> 99 159892 [main] sh 2880 fhandler_base_overlapped::wait_overlapped:
> normal write, 7 bytes ispipe() 1
>
> 180 1609127 [main] make 11484 fhandler_base_overlapped::wait_overlapped:
> normal read, 7 bytes ispipe() 1
>
> 139 160031 [main] sh 2880 write: 7 = write(1, 0x6000396A0, 7)
>
> 142 1609269 [main] make 11484 fhandler_base::read: returning 7, binary
> mode
>
> 139 1609408 [main] make 11484 read: 7 = read(5, 0x60005B4B0, 7)
>
> 136 1609544 [main] make 11484 read: read(5, 0x60005B4B7, 193) blocking
>
> 4693 164724 [main] sh 2880 set_signal_mask: setmask 0, newmask 80000,
> mask_bits 0
>
> but with hundreds of thousands of lines. (I have not counted)
>
> I believe that it may be the result of this line, earlier in the log
>
> cd "/c/Users/simonpj/AppData/Local/Temp/ghctest-8fa9s6rk/test
> spaces/./plugins/plugins07.run" && *strace* $MAKE -s --no-print-directory
> -C rule-defining-plugin package.plugins07 TOP=/c/code/HEAD/testsuite#
>
> Note the strace.
>
> That in turn was added in your commit
>
> commit 60fb2b2160aa16194b74262f4df8fad5af171b0f
>
> Author: Tamar Christina <tamar at zhox.com>
>
> Date: Mon May 28 19:34:11 2018 +0100
>
>
>
> Clean up Windows testsuite failures
>
>
>
> Summary:
>
> Another round and attempt at getting these down to 0.
>
> Could you perhaps have made a mistake here? Currently validate is
> unusable.
>
> Thanks!
>
> Simon
>
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.haskell.org/pipermail/ghc-devs/attachments/20180618/1b7bf7d8/attachment.html>
More information about the ghc-devs
mailing list