Open jlapeyre opened 4 years ago
Just curious: what were you doing that logging was a significant bottleneck? Calling the "expectation" endpoint? That's the only place I see where qvm-app is logging in a loop. Every other request type should result in only a few 10s of log messages per request. Or was it just lots of short requests in parallel?
The following repeatedly. There are 2200 lines in 1s. The program has parameterized gates. I change the parameters and run program in a loop.
Oct 15 21:03:05 ribot qvm[12718]: <134>1 2019-10-16T04:03:05Z ribot qvm 12718 - - 127.0.0.1 - [2019-10-15 21:03:05] "POST /qvm HTTP/1.1" 200 294 "-" "python-requests/2.22.0"
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Got "expectation" request from API key/User ID: NIL / NIL
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Making qvm of 4 qubits
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing initial state for expectation value computation on PURE-STATE-QVM
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Finished state prep in 1 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Copying prepared state.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Copied prepared state in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the first operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed first expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the second operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed second expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the third operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed third expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the fourth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed fourth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the fifth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed fifth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the sixth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed sixth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the seventh operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed seventh expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the eighth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed eighth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the ninth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed ninth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the tenth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed tenth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the eleventh operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed eleventh expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the twelfth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed twelfth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the thirteenth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed thirteenth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the fourteenth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed fourteenth expectation value in 0 ms.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computing the expectation value of the fifteenth operator.
Oct 15 21:03:05 ribot qvm[12718]: <135>1 2019-10-16T04:03:05Z ribot qvm 12718 - - [127.0.0.1 Session:510] Computed fifteenth expectation value in 0 ms.
The cli help string notes that the default log-level is
debug
. In some cases, this causes significant cpu usage. It's easy to turn off, but a user might not notice this. Or like me, it might take a few minutes to diagnose.Explaining this in the README might be useful.
OTOH, I found my answer in the help string. I only discovered that it's not in the README when I started this issue.