Closed bscottm closed 6 years ago
@mvoidex: Possible thread contention wtih SQLite?
The problem manifests itself as a short read on the SH client -- SH sees an incomplete (short) response. Somewhat wondering if the socket needs to be forcibly flushed. I'll experiment and report back.
However, the command line version is hosed
complete
command expects prefix, but you can pass empty one:
hsdev complete "" --file <file>
Yes, it's slow. I'll try to figure out, what's wrong
Actually, I'm coming to the conclusion that it's the network
library that's broken (again) for the same reason related to your previous bug report on the GHC Trac. I'll try to confirm via wireshark
to capture the incomplete hsdev
socket write.
If I increase the hsdev/client.py
read buffer size to 65536, there is no stall. But, if the size is 10240 (now), SH does multiple reads, the last of which is obviously incomplete. I also get a lot of messages from hsdev
about kevent: invalid descriptor
, which would also seem to point in the direction of the network
runtime.
Here's a hsdev
session that I just captured -- stalls in complete
, but then dies in usages
:
2018-04-19 10:19:09 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:09 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:09 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:10 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:10 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:10 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:10 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:10 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:10 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:10 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:10 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:10 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:10 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:10 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:10 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:10 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:10 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:10 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:10 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:10 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:10 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:10 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:11 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:11 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:11 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:11 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:11 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:11 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:11 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:11 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:11 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:11 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:11 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:11 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:11 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:11 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:11 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:11 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:11 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:11 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:11 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:11 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:11 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:12 -0700 TRACE sqlite:update/scan-project-file/update-project> update project: edas
2018-04-19 10:19:12 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:12 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:12 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:12 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:12 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:12 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:12 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:12 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:12 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:12 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:12 -0700 TRACE sqlite:update/scan-project-file/update-project> update project: emubase
2018-04-19 10:19:12 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:12 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:12 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:12 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:12 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:12 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:12 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:12 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:12 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:12 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:13 -0700 TRACE sqlite:update/scan-project-file/update-project> update project: emuwork
2018-04-19 10:19:13 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:13 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:13 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:13 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:13 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:13 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:13 -0700 TRACE :ghc> killing session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:13 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:13 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:13 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:13 -0700 TRACE sqlite:update/scan-project-file/update-project> update project: trs80
2018-04-19 10:19:13 -0700 TRACE :ghc> session: tmp global-db
2018-04-19 10:19:13 -0700 TRACE :ghc> setting flags: -no-user-package-db
2018-04-19 10:19:13 -0700 TRACE :ghc> invoking stack: /usr/local/bin/stack --compiler ghc-8.2.2 --arch x86_64 path
2018-04-19 10:19:13 -0700 TRACE :ghc> killing session: tmp global-db
2018-04-19 10:19:13 -0700 TRACE :ghc> session: tmp global-db/package-db /Users/bsm21317/.stack/snapshots/x86_64-osx/lts-11.5/8.2.2/pkgdb/package-db /Users/bsm21317/play/emuwork/.stack-work/install/x86_64-osx/lts-11.5/8.2.2/pkgdb
2018-04-19 10:19:13 -0700 TRACE :ghc> setting flags:
2018-04-19 10:19:13 -0700 TRACE :update/task/directory/task/package-db> package-db state: 25 modules
2018-04-19 10:19:13 -0700 TRACE :update/task/directory/task/package-db> nothing changes, all packages the same
2018-04-19 10:19:14 -0700 TRACE :update/task/directory/task/package-db> package-db state: 733 modules
2018-04-19 10:19:14 -0700 TRACE :update/task/directory/task/package-db> nothing changes, all packages the same
2018-04-19 10:19:14 -0700 TRACE :update/task/directory/task/package-db> package-db state: 1165 modules
2018-04-19 10:19:14 -0700 TRACE :update/task/directory/task/package-db> nothing changes, all packages the same
2018-04-19 10:19:14 -0700 DEBUG :update> updated 0 modules
2018-04-19 10:19:14 -0700 TRACE :127.0.0.1:60834/127.0.0.1:60834/req/3> responsed << {"result":[]}
2018-04-19 10:19:14 -0700 TRACE :127.0.0.1:60832> received >> {"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","no-file":true,"command":"complete","wide":false,"prefix":"","id":"4"}
2018-04-19 10:19:14 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/4> requested >> {"command":"complete","wide":false,"prefix":"","file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"}
2018-04-19 10:19:14 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/4> responsed << {"result":[{"id":{"name":"!","module":{"location":{"dirs":["/Users/bsm21317/.stack/snapshots/x86_64-...
2018-04-19 10:24:14 -0700 TRACE :127.0.0.1:60828> received >> {"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","no-file":true,"command":"complete","wide":false,"prefix":"","id":"5"}
2018-04-19 10:24:14 -0700 TRACE :127.0.0.1:60828/127.0.0.1:60828/req/5> requested >> {"command":"complete","wide":false,"prefix":"","file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"}
2018-04-19 10:24:14 -0700 TRACE :127.0.0.1:60828/127.0.0.1:60828/req/5> responsed << {"result":[{"id":{"name":"!","module":{"location":{"dirs":["/Users/bsm21317/.stack/snapshots/x86_64-...
2018-04-19 10:24:14 -0700 TRACE :127.0.0.1:60834> received >> {"query":{"input":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","type":"prefix"},"header":false,"command":"module","filters":[],"id":"6","no-file":true,"inspection":false}
2018-04-19 10:24:14 -0700 TRACE :127.0.0.1:60834/127.0.0.1:60834/req/6> requested >> {"command":"module","filters":[],"inspection":false,"header":false,"query":{"input":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","type":"prefix"}}
2018-04-19 10:24:14 -0700 TRACE :127.0.0.1:60834/127.0.0.1:60834/req/6> responsed << {"result":[]}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60832> received >> {"projects":[],"files":["/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"],"no-file":true,"command":"infer","id":"7"}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60832> received >> {"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","no-file":true,"command":"whoat","column":70,"id":"8","line":55}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/7> requested >> {"command":"infer","files":["/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"],"projects":[]}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/8> requested >> {"command":"whoat","line":55,"column":70,"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"}
2018-04-19 10:25:59 -0700 DEBUG :update> updated 0 modules
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/7> responsed << {"result":[]}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/8> responsed << {"result":[{"id":{"name":"Int","module":{"location":{"dirs":["/Users/bsm21317/.stack/programs/x86_64...
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60828> received >> {"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","no-file":true,"command":"usages","column":70,"id":"9","line":55}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60828/127.0.0.1:60828/req/9> requested >> {"command":"usages","line":55,"column":70,"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"}
2018-04-19 10:25:59 -0700 TRACE :127.0.0.1:60828/127.0.0.1:60828/req/9> responsed << {"result":[{"at":{"to":{"line":33,"column":25},"from":{"line":33,"column":22}},"symbol":{"id":{"name...
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60834> received >> {"projects":[],"files":["/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"],"no-file":true,"command":"infer","id":"10"}
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60832> received >> {"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","no-file":true,"command":"whoat","column":30,"id":"11","line":31}
2018-04-19 10:26:29 -0700 INFO :127.0.0.1:60834> disconnected
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/11> requested >> {"command":"whoat","line":31,"column":30,"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"}
2018-04-19 10:26:29 -0700 TRACE :> stopping server
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60834/127.0.0.1:60834/req/10> requested >> {"command":"infer","files":["/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"],"projects":[]}
2018-04-19 10:26:29 -0700 ERROR :127.0.0.1:60834> exception: kevent: invalid argument (Bad file descriptor)
2018-04-19 10:26:29 -0700 TRACE :> accept thread stopped
2018-04-19 10:26:29 -0700 TRACE :> waiting for clients...
2018-04-19 10:26:29 -0700 TRACE :> waiting for 127.0.0.1:60828 to complete
2018-04-19 10:26:29 -0700 DEBUG :update> updated 0 modules
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60834/127.0.0.1:60834/req/10> responsed << {"result":[]}
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60832/127.0.0.1:60832/req/11> responsed << {"result":[{"pos":{"line":166,"column":6},"id":{"name":"DeviceManager","module":{"location":{"projec...
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60830> received >> {"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs","no-file":true,"command":"usages","column":30,"id":"12","line":31}
2018-04-19 10:26:29 -0700 INFO :127.0.0.1:60830> disconnected
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60830/127.0.0.1:60830/req/12> requested >> {"command":"usages","line":31,"column":30,"file":"/Users/bsm21317/play/emuwork/src-emubase/Machine/Types.hs"}
2018-04-19 10:26:29 -0700 ERROR :127.0.0.1:60830> exception: kevent: invalid argument (Bad file descriptor)
2018-04-19 10:26:29 -0700 TRACE :127.0.0.1:60830/127.0.0.1:60830/req/12> responsed << {"result":[{"at":{"to":{"line":166,"column":19},"from":{"line":166,"column":6}},"symbol":{"pos":{"li...
2018-04-19 10:26:30 -0700 INFO :127.0.0.1:60828> disconnected
2018-04-19 10:26:30 -0700 TRACE :> waiting for 127.0.0.1:60832 to complete
2018-04-19 10:26:30 -0700 FATAL :127.0.0.1:60828> thread killed
2018-04-19 10:26:30 -0700 ERROR :127.0.0.1:60828> Scope leaves with exception: thread killed
CallStack (from HasCallStack):
onError, called at src/System/Log/Simple/Monad.hs:104:36 in simple-log-0.9.3-D7FFRtyRsD8LeUQVCSVbtv:System.Log.Simple.Monad
2018-04-19 10:26:31 -0700 TRACE :> waiting for 127.0.0.1:60835 to complete
2018-04-19 10:26:31 -0700 INFO :127.0.0.1:60832> disconnected
2018-04-19 10:26:31 -0700 FATAL :127.0.0.1:60832> thread killed
2018-04-19 10:26:31 -0700 ERROR :127.0.0.1:60832> Scope leaves with exception: thread killed
CallStack (from HasCallStack):
onError, called at src/System/Log/Simple/Monad.hs:104:36 in simple-log-0.9.3-D7FFRtyRsD8LeUQVCSVbtv:System.Log.Simple.Monad
@mvoidex: I've captured a packet trace between SH and hsdev
and confirmed that complete
does send an incomplete response. I don't think the problem is hsdev
itself because wireshark
does show that hsdev
stops sending data, with subsequent "invalid file descriptor messages" in stderr
. That would lead me to conclude that the network-2.6.3.5
package is reaping socket/file descriptors before their time or that the sendAll
function is misimplemented or something else funky is going on in encode
.
Doesn't matter if hsdev
is built with 8.0.2 or 8.2.2.
Is it fixed with #87?
Unable to stall hsdev
... so far.
I'm trying to diagnose a SH freeze that happens when invoking the
complete
command. However, the command line version is hosed:Currently,
complete
will cause SH to freeze for 5 minutes (the default timeout forhsdev
responses). Would like to figure out why. The JSON is similar to the command line:(BTW: I propagated the new and changed
hsdev
backend methods to theNoneBackend
and theHaskellBackend
classes. Really should consider runningpylint
after you hack on SH. You would be surprised at the number of people who actually use the "none" backend, which makes its functionality very important. As important ashsdev
. :-)