{"action":"opened","issue":{"url":"https://api.github.com/repos/stellar/stellar-core/issues/1774","repository_url":"https://api.github.com/repos/stellar/stellar-core","labels_url":"https://api.github.com/repos/stellar/stellar-core/issues/1774/labels{/name}","comments_url":"https://api.github.com/repos/stellar/stellar-core/issues/1774/comments","events_url":"https://api.github.com/repos/stellar/stellar-core/issues/1774/events","html_url":"https://github.com/stellar/stellar-core/issues/1774","id":356069258,"node_id":"MDU6SXNzdWUzNTYwNjkyNTg=","number":1774,"title":"Latency in main thread while publishing","user":{"login":"MonsieurNicolas","id":4213763,"node_id":"MDQ6VXNlcjQyMTM3NjM=","avatar_url":"https://avatars3.githubusercontent.com/u/4213763?v=4","gravatar_id":"","url":"https://api.github.com/users/MonsieurNicolas","html_url":"https://github.com/MonsieurNicolas","followers_url":"https://api.github.com/users/MonsieurNicolas/followers","following_url":"https://api.github.com/users/MonsieurNicolas/following{/other_user}","gists_url":"https://api.github.com/users/MonsieurNicolas/gists{/gist_id}","starred_url":"https://api.github.com/users/MonsieurNicolas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/MonsieurNicolas/subscriptions","organizations_url":"https://api.github.com/users/MonsieurNicolas/orgs","repos_url":"https://api.github.com/users/MonsieurNicolas/repos","events_url":"https://api.github.com/users/MonsieurNicolas/events{/privacy}","received_events_url":"https://api.github.com/users/MonsieurNicolas/received_events","type":"User","site_admin":false},"labels":[{"id":150967169,"node_id":"MDU6TGFiZWwxNTA5NjcxNjk=","url":"https://api.github.com/repos/stellar/stellar-core/labels/bug","name":"bug","color":"fc2929","default":true},{"id":189017016,"node_id":"MDU6TGFiZWwxODkwMTcwMTY=","url":"https://api.github.com/repos/stellar/stellar-core/labels/performance","name":"performance","color":"fbca04","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2018-08-31T17:44:59Z","updated_at":"2018-08-31T17:44:59Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"# Issue type\r\n  bug\r\n\r\n# Version found\r\n10.0.0rc3\r\n\r\n# Issue description\r\nLooks like validators hang for a few seconds every time a snapshot is taken.\r\n\r\nThis seems to happen all the time on testnet (with ~ constant traffic)\r\n\r\n## Actual result\r\n![image](https://user-images.githubusercontent.com/4213763/44927753-8bb56800-ad0a-11e8-9c5d-22e78356df98.png)\r\n\r\n\r\n## Expected result\r\nTaking and uploading snapshots should happen in the background.\r\n\r\n## Supporting files\r\n\r\nSo far the only thing I found in the logs is this (note the absence of overlay messages - and the 2 seconds pause with no logs at the end)\r\n```\r\n2018-08-29T16:28:16.537 GDKXE [Overlay TRACE] Debiting peer GDEIP time:9us send:0 recv:4B query:0 [LoadManager.cpp:190]\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] resetting prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] work prepare-snapshot : WORK_FAILURE_RETRY -> WORK_PENDING\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] advancing prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] all 0 children of prepare-snapshot successful, scheduling run\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] scheduling run of prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] starting prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] running prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] work prepare-snapshot : WORK_PENDING -> WORK_RUNNING\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] scheduling completion of prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] completed prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] work prepare-snapshot : WORK_RUNNING -> WORK_SUCCESS\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] notifying parent of successful prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] notified publish-00a48fff of completed child prepare-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] advancing publish-00a48fff\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] all 1 children of publish-00a48fff successful, scheduling run\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] scheduling run of publish-00a48fff\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] starting publish-00a48fff\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] running publish-00a48fff\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] work publish-00a48fff : WORK_PENDING -> WORK_RUNNING\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] scheduling completion of publish-00a48fff\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] completed publish-00a48fff\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] resetting write-snapshot\r\n2018-08-29T16:28:16.599 GDKXE [Work DEBUG] work publish-00a48fff : WORK_RUNNING -> WORK_PENDING\r\n2018-08-29T16:28:16.600 GDKXE [Work DEBUG] advancing publish-00a48fff\r\n2018-08-29T16:28:16.600 GDKXE [Work DEBUG] advancing write-snapshot\r\n2018-08-29T16:28:16.600 GDKXE [Work DEBUG] all 0 children of write-snapshot successful, scheduling run\r\n2018-08-29T16:28:16.600 GDKXE [Work DEBUG] scheduling run of write-snapshot\r\n2018-08-29T16:28:16.600 GDKXE [Work DEBUG] starting write-snapshot\r\n2018-08-29T16:28:16.600 GDKXE [History DEBUG] Streaming 64 ledgers worth of history, from 10784704\r\n2018-08-29T16:28:16.602 GDKXE [Work DEBUG] running write-snapshot\r\n2018-08-29T16:28:16.602 GDKXE [Work DEBUG] work write-snapshot : WORK_PENDING -> WORK_RUNNING\r\n2018-08-29T16:28:16.602 GDKXE [Ledger DEBUG] Streaming ledger-header 10784704\r\n...\r\n2018-08-29T16:28:16.609 GDKXE [Ledger DEBUG] Streaming ledger-header 10784767\r\n2018-08-29T16:28:16.628 GDKXE [History DEBUG] Wrote 64 ledger headers to /data/buckets/tmp/snapshot-cbd07e30c2380274/ledger-00a48fff.xdr\r\n2018-08-29T16:28:16.628 GDKXE [History DEBUG] Wrote 160 transactions to /data/buckets/tmp/snapshot-cbd07e30c2380274/transactions-00a48fff.xdr and /data/buckets/tmp/snapshot-cbd07e30c2380274/results-00a48fff.xdr\r\n2018-08-29T16:28:16.675 GDKXE [History DEBUG] Wrote 188 SCP messages to /data/buckets/tmp/snapshot-cbd07e30c2380274/scp-00a48fff.xdr\r\n2018-08-29T16:28:16.676 GDKXE [Work DEBUG] completed write-snapshot\r\n2018-08-29T16:28:16.676 GDKXE [Work DEBUG] work write-snapshot : WORK_RUNNING -> WORK_SUCCESS\r\n2018-08-29T16:28:16.676 GDKXE [Work DEBUG] notifying parent of successful write-snapshot\r\n2018-08-29T16:28:16.676 GDKXE [Work DEBUG] notified publish-00a48fff of completed child write-snapshot\r\n2018-08-29T16:28:16.676 GDKXE [Work DEBUG] advancing publish-00a48fff\r\n2018-08-29T16:28:16.676 GDKXE [Work DEBUG] all 2 children of publish-00a48fff successful, scheduling run\r\n2018-08-29T16:28:16.677 GDKXE [Work DEBUG] scheduling run of publish-00a48fff\r\n2018-08-29T16:28:16.677 GDKXE [Work DEBUG] starting publish-00a48fff\r\n2018-08-29T16:28:16.677 GDKXE [Work DEBUG] running publish-00a48fff\r\n2018-08-29T16:28:16.677 GDKXE [Work DEBUG] work publish-00a48fff : WORK_PENDING -> WORK_RUNNING\r\n2018-08-29T16:28:16.677 GDKXE [Work DEBUG] scheduling completion of publish-00a48fff\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] completed publish-00a48fff\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] resetting update-archives\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] resetting put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] work publish-00a48fff : WORK_RUNNING -> WORK_PENDING\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] advancing publish-00a48fff\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] advancing update-archives\r\n2018-08-29T16:28:16.678 GDKXE [Work DEBUG] advancing put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] all 0 children of put-snapshot-files-core_testnet_001 successful, scheduling run\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] scheduling run of put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] starting put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] running put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] work put-snapshot-files-core_testnet_001 : WORK_PENDING -> WORK_RUNNING\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] scheduling completion of put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] completed put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.679 GDKXE [Work DEBUG] resetting get-history-archive-state\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] resetting get-remote-file .well-known/stellar-history.json\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] work put-snapshot-files-core_testnet_001 : WORK_RUNNING -> WORK_PENDING\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] advancing put-snapshot-files-core_testnet_001\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] advancing get-history-archive-state\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] advancing get-remote-file .well-known/stellar-history.json\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] all 0 children of get-remote-file .well-known/stellar-history.json successful, scheduling run\r\n2018-08-29T16:28:16.680 GDKXE [Work DEBUG] scheduling run of get-remote-file .well-known/stellar-history.json\r\n2018-08-29T16:28:16.681 GDKXE [Work DEBUG] starting get-remote-file .well-known/stellar-history.json\r\n2018-08-29T16:28:16.681 GDKXE [Process DEBUG] Running: aws s3 cp --region eu-west-1 s3://history.stellar.org/prd/core-testnet/core_testnet_001/.well-known/stellar-history.json /data/buckets/tmp/history-03d643844ea2671e/core_testnet_001-stellar-history.json\r\n2018-08-29T16:28:16.853 GDKXE [Work DEBUG] running get-remote-file .well-known/stellar-history.json\r\n2018-08-29T16:28:16.854 GDKXE [Work DEBUG] work get-remote-file .well-known/stellar-history.json : WORK_PENDING -> WORK_RUNNING\r\nCompleted 3.8 KiB/3.8 KiB (11.3 KiB/s) with 1 file(s) remaining^Mdownload: s3://history.stellar.org/prd/core-testnet/core_testnet_001/.well-known/stellar-history.json to data/buckets/tmp/history-03d643844ea2671e/core_testnet_001-stellar-history.json\r\n2018-08-29T16:28:18.034 GDKXE [Overlay TRACE] TCPPeer::startRead calledback system:0 length:4 [TCPPeer.cpp:328]\r\n2018-08-29T16:28:18.035 GDKXE [Overlay TRACE] Debiting peer GAVSH time:47us send:0 recv:4B query:0 [LoadManager.cpp:190]\r\n```\r\n"}}
{"actor":{"display_login":"MonsieurNicolas"}}