Skip to content

Instantly share code, notes, and snippets.

Show Gist options
  • Save a-robinson/17ebf561bf450b40e7e89edd967962ca to your computer and use it in GitHub Desktop.
Save a-robinson/17ebf561bf450b40e7e89edd967962ca to your computer and use it in GitHub Desktop.
26951.669ms 0.024ms event:[n1,client=10.142.15.204:47136,user=root] Scan /Table/55/1/900{-/#}
26951.679ms 0.010ms operation:dist sender
26951.690ms 0.011ms event:[client=10.142.15.204:47136,user=root,txn=779a7ccb,n1] querying next range at /Table/55/1/900
26951.724ms 0.034ms event:[client=10.142.15.204:47136,user=root,txn=779a7ccb,n1] r55510: sending batch 1 Scan to (n11,s11):2
26951.746ms 0.022ms event:[client=10.142.15.204:47136,user=root,txn=779a7ccb,n1] sending request to alex-tpcc-0027:26257
26951.761ms 0.014ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnID:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
26953.002ms 1.242ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
26953.040ms 0.038ms event:[n11] 1 Scan
26953.049ms 0.008ms event:[n11,s11] executing 1 requests
26953.057ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
26953.074ms 0.016ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
26953.096ms 0.022ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for 1 overlapping requests
27558.803ms 605.707ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waited 605.710986ms for overlapping requests
27558.834ms 0.031ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
27559.012ms 0.178ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] engine stats: {InternalDeleteSkippedCount:4 TimeBoundNumSSTs:0}
27559.046ms 0.034ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] conflicting intents on /Table/55/1/900/0
27559.074ms 0.028ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] replica.Send got error: conflicting intents on /Table/55/1/900/0
27559.081ms 0.007ms event:[n11,s11] pushing 1 transaction(s)
27559.092ms 0.011ms operation:dist sender
27559.111ms 0.019ms event:[s11,n11] querying next range at /Table/55/1/900/0
27559.150ms 0.039ms event:[s11,n11] r55510: sending batch 1 PushTxn to (n11,s11):2
27559.171ms 0.021ms event:[s11,n11] sending request to local server
27559.188ms 0.017ms operation:/cockroach.roachpb.Internal/Batch
27559.194ms 0.006ms event:[n11] 1 PushTxn
27559.216ms 0.022ms event:[n11,s11] executing 1 requests
27559.228ms 0.012ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
27559.236ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
27559.257ms 0.021ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for 2 overlapping requests
27560.376ms 1.119ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waited 1.119079ms for overlapping requests
27560.380ms 0.004ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
27560.499ms 0.119ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
27560.512ms 0.013ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] replica.Send got error: failed to push "sql txn" id=3decefa8 key=/Table/55/1/900/0 rw=true pri=0.05884850 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527653712.440190569,4 orig=1527653699.331424829,0 max=1527653699.373578010,0 wto=false rop=false seq=8
27560.574ms 0.062ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] 779a7ccb pushing 3decefa8 (1 pending)
27560.586ms 0.012ms operation:[async] monitoring pusher txn sb:1 txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27560.654ms 0.069ms operation:dist sender
27560.695ms 0.041ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
27560.738ms 0.042ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
27560.759ms 0.021ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
27560.788ms 0.029ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27561.410ms 0.622ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] querying pushee
27561.426ms 0.017ms operation:dist sender
27561.449ms 0.022ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
27561.485ms 0.036ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
27561.505ms 0.021ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
27561.522ms 0.017ms operation:/cockroach.roachpb.Internal/Batch
27561.528ms 0.006ms event:[n11] 1 QueryTxn
27561.535ms 0.007ms event:[n11,s11] executing 1 requests
27561.542ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
27561.560ms 0.018ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
27561.568ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
27561.608ms 0.040ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27561.630ms 0.022ms event:[n20] 1 QueryTxn
27561.637ms 0.006ms event:[n20,s19] executing 1 requests
27561.697ms 0.060ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
27611.803ms 50.106ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
27611.812ms 0.010ms event:[n20,s19,r1/8:/{Min-System/}] command queue
27611.817ms 0.005ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
27611.871ms 0.054ms event:[n20,s19,r1/8:/{Min-System/}] read completed
27612.052ms 0.181ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
27695.787ms 83.736ms operation:dist sender
27695.808ms 0.021ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
27695.837ms 0.029ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
27695.854ms 0.017ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
27695.874ms 0.020ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27696.248ms 0.374ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27696.267ms 0.019ms event:[n20] 1 QueryTxn
27696.271ms 0.004ms event:[n20,s19] executing 1 requests
27746.401ms 50.130ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
27746.409ms 0.007ms event:[n20,s19,r1/8:/{Min-System/}] command queue
27746.413ms 0.004ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
27746.490ms 0.077ms event:[n20,s19,r1/8:/{Min-System/}] read completed
27746.930ms 0.441ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
27889.409ms 142.478ms operation:dist sender
27889.441ms 0.033ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
27889.492ms 0.051ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
27889.524ms 0.032ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
27889.546ms 0.022ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27890.105ms 0.559ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
27890.121ms 0.016ms event:[n20] 1 QueryTxn
27890.125ms 0.005ms event:[n20,s19] executing 1 requests
27940.202ms 50.076ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
27940.216ms 0.014ms event:[n20,s19,r1/8:/{Min-System/}] command queue
27940.221ms 0.006ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
27940.291ms 0.070ms event:[n20,s19,r1/8:/{Min-System/}] read completed
27943.851ms 3.560ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
28254.895ms 311.045ms operation:dist sender
28254.929ms 0.033ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
28254.996ms 0.067ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
28255.322ms 0.326ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
28255.353ms 0.031ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
28260.233ms 4.880ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
28260.276ms 0.043ms event:[n20] 1 QueryTxn
28260.283ms 0.007ms event:[n20,s19] executing 1 requests
28310.465ms 50.181ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
28310.485ms 0.021ms event:[n20,s19,r1/8:/{Min-System/}] command queue
28310.489ms 0.003ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
28310.583ms 0.094ms event:[n20,s19,r1/8:/{Min-System/}] read completed
28310.835ms 0.252ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
28327.333ms 16.498ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] querying pushee
28327.348ms 0.015ms operation:dist sender
28327.371ms 0.022ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
28371.671ms 44.300ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
28371.701ms 0.030ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
28371.737ms 0.036ms operation:/cockroach.roachpb.Internal/Batch
28371.746ms 0.008ms event:[n11] 1 QueryTxn
28371.753ms 0.007ms event:[n11,s11] executing 1 requests
28371.762ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
28371.770ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
28371.779ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
28371.893ms 0.113ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
28665.493ms 293.600ms operation:dist sender
28665.513ms 0.020ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
28665.552ms 0.040ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
28665.574ms 0.022ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
28665.607ms 0.033ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
28666.359ms 0.752ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
28666.390ms 0.031ms event:[n20] 1 QueryTxn
28666.397ms 0.007ms event:[n20,s19] executing 1 requests
28716.531ms 50.134ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
28716.541ms 0.011ms event:[n20,s19,r1/8:/{Min-System/}] command queue
28716.642ms 0.101ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
28716.712ms 0.069ms event:[n20,s19,r1/8:/{Min-System/}] read completed
28716.967ms 0.256ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
28905.062ms 188.095ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] result of pending push: "sql txn" id=3decefa8 key=/Table/55/1/900/0 rw=true pri=0.05884850 iso=SERIALIZABLE stat=COMMITTED epo=1 ts=1527653712.440190569,4 orig=1527653712.440190569,4 max=1527653699.373578010,0 wto=false rop=false seq=30 int=8
28905.067ms 0.005ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] push request is satisfied
28905.135ms 0.068ms event:[n11,s11] 3decefa8-230a-4da9-8f9b-bb1c0ad7df07 is now COMMITTED
28905.138ms 0.004ms event:[n11,s11] resolving intents [wait=false]
28905.152ms 0.014ms operation:dist sender
28905.169ms 0.017ms event:[s11,n11] querying next range at /Table/55/1/900/0
28905.206ms 0.037ms event:[s11,n11] r55510: sending batch 1 ResolveIntent to (n11,s11):2
28905.223ms 0.017ms event:[s11,n11] sending request to local server
28905.239ms 0.016ms operation:/cockroach.roachpb.Internal/Batch
28905.246ms 0.007ms event:[n11] 1 ResolveIntent
28905.253ms 0.006ms event:[n11,s11] executing 1 requests
28905.260ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
28905.266ms 0.005ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
28905.282ms 0.016ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for 1 overlapping requests
29248.227ms 342.945ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waited 342.938766ms for overlapping requests
29248.237ms 0.010ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
29248.447ms 0.209ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
29248.506ms 0.060ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
29248.515ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
29248.527ms 0.011ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
29248.688ms 0.161ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] engine stats: {InternalDeleteSkippedCount:4 TimeBoundNumSSTs:0}
29248.728ms 0.040ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] conflicting intents on /Table/55/1/900/0
29248.759ms 0.031ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] replica.Send got error: conflicting intents on /Table/55/1/900/0
29248.766ms 0.007ms event:[n11,s11] pushing 1 transaction(s)
29248.780ms 0.014ms operation:dist sender
29248.797ms 0.017ms event:[s11,n11] querying next range at /Table/55/1/900/0
29248.840ms 0.042ms event:[s11,n11] r55510: sending batch 1 PushTxn to (n11,s11):2
29248.857ms 0.018ms event:[s11,n11] sending request to local server
29248.874ms 0.017ms operation:/cockroach.roachpb.Internal/Batch
29248.880ms 0.006ms event:[n11] 1 PushTxn
29248.888ms 0.007ms event:[n11,s11] executing 1 requests
29248.900ms 0.012ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
29248.907ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
29248.921ms 0.014ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
29249.082ms 0.161ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
29249.109ms 0.027ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] replica.Send got error: failed to push "sql txn" id=396e1869 key=/Table/55/1/900/0 rw=true pri=0.03680186 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527653712.440190569,5 orig=1527653693.090879831,0 max=1527653693.096856616,0 wto=false rop=false seq=10
29249.134ms 0.025ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] 779a7ccb pushing 396e1869 (1 pending)
29249.145ms 0.011ms operation:[async] monitoring pusher txn sb:1 txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29249.178ms 0.033ms operation:dist sender
29249.201ms 0.023ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
29249.702ms 0.501ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
29249.736ms 0.033ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
29249.758ms 0.022ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29250.162ms 0.404ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29250.183ms 0.020ms event:[n20] 1 QueryTxn
29250.188ms 0.006ms event:[n20,s19] executing 1 requests
29255.367ms 5.179ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] querying pushee
29255.381ms 0.014ms operation:dist sender
29255.414ms 0.033ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
29255.451ms 0.038ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
29255.483ms 0.032ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
29255.499ms 0.016ms operation:/cockroach.roachpb.Internal/Batch
29255.507ms 0.008ms event:[n11] 1 QueryTxn
29255.513ms 0.006ms event:[n11,s11] executing 1 requests
29255.521ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
29255.529ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
29255.535ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
29255.684ms 0.149ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
29300.355ms 44.671ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
29300.363ms 0.008ms event:[n20,s19,r1/8:/{Min-System/}] command queue
29300.369ms 0.006ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
29300.420ms 0.051ms event:[n20,s19,r1/8:/{Min-System/}] read completed
29304.637ms 4.218ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
29351.708ms 47.070ms operation:dist sender
29351.725ms 0.018ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
29351.763ms 0.037ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
29351.784ms 0.021ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
29351.804ms 0.020ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29352.334ms 0.530ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29352.354ms 0.020ms event:[n20] 1 QueryTxn
29352.359ms 0.005ms event:[n20,s19] executing 1 requests
29402.465ms 50.106ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
29402.473ms 0.007ms event:[n20,s19,r1/8:/{Min-System/}] command queue
29402.478ms 0.006ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
29402.548ms 0.070ms event:[n20,s19,r1/8:/{Min-System/}] read completed
29418.869ms 16.321ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
29530.911ms 112.042ms operation:dist sender
29530.926ms 0.015ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
29530.962ms 0.036ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
29530.981ms 0.019ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
29531.000ms 0.020ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29531.401ms 0.401ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
29531.431ms 0.029ms event:[n20] 1 QueryTxn
29531.436ms 0.005ms event:[n20,s19] executing 1 requests
29581.563ms 50.126ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
29581.571ms 0.009ms event:[n20,s19,r1/8:/{Min-System/}] command queue
29581.579ms 0.008ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
29581.632ms 0.052ms event:[n20,s19,r1/8:/{Min-System/}] read completed
29706.976ms 125.345ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
29975.198ms 268.222ms operation:dist sender
29975.227ms 0.029ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
30134.600ms 159.374ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
30134.655ms 0.055ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
30134.680ms 0.025ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
30135.009ms 0.329ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
30135.028ms 0.019ms event:[n20] 1 QueryTxn
30135.035ms 0.006ms event:[n20,s19] executing 1 requests
30185.173ms 50.139ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
30185.181ms 0.008ms event:[n20,s19,r1/8:/{Min-System/}] command queue
30185.187ms 0.006ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
30185.233ms 0.046ms event:[n20,s19,r1/8:/{Min-System/}] read completed
30185.348ms 0.115ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
30575.736ms 390.389ms operation:dist sender
30575.767ms 0.030ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Min
30575.806ms 0.040ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r1: sending batch 1 QueryTxn to (n20,s19):8
30575.827ms 0.021ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to alex-tpcc-0002:26257
30575.848ms 0.021ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
30576.756ms 0.908ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
30576.776ms 0.019ms event:[n20] 1 QueryTxn
30576.781ms 0.005ms event:[n20,s19] executing 1 requests
30626.903ms 50.122ms event:[n20,s19,r1/8:/{Min-System/}] read-only path
30626.914ms 0.011ms event:[n20,s19,r1/8:/{Min-System/}] command queue
30626.918ms 0.004ms event:[n20,s19,r1/8:/{Min-System/}] waiting for read lock
30626.970ms 0.052ms event:[n20,s19,r1/8:/{Min-System/}] read completed
30627.284ms 0.314ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
30654.430ms 27.146ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] result of pending push: "sql txn" id=396e1869 key=/Table/55/1/900/0 rw=true pri=0.04831478 iso=SERIALIZABLE stat=COMMITTED epo=1 ts=1527653712.440190569,5 orig=1527653712.440190569,5 max=1527653693.096856616,0 wto=false rop=false seq=32 int=8
30654.434ms 0.004ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] push request is satisfied
30654.520ms 0.086ms event:[n11,s11] 396e1869-4fff-4985-bb80-1f4c9289fa07 is now COMMITTED
30654.524ms 0.004ms event:[n11,s11] resolving intents [wait=false]
30654.542ms 0.018ms operation:dist sender
30654.564ms 0.021ms event:[s11,n11] querying next range at /Table/55/1/900/0
30654.618ms 0.054ms event:[s11,n11] r55510: sending batch 1 ResolveIntent to (n11,s11):2
30654.638ms 0.019ms event:[s11,n11] sending request to local server
30654.655ms 0.017ms operation:/cockroach.roachpb.Internal/Batch
30654.664ms 0.010ms event:[n11] 1 ResolveIntent
30654.671ms 0.006ms event:[n11,s11] executing 1 requests
30654.678ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
30654.700ms 0.021ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
30654.711ms 0.011ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
30654.929ms 0.219ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
30654.965ms 0.036ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
30654.975ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
30654.983ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
30655.493ms 0.511ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] engine stats: {InternalDeleteSkippedCount:6 TimeBoundNumSSTs:0}
30655.500ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
30659.959ms 4.459ms event:util/mon/bytes_usage.go:576 [n1,client=10.142.15.204:47136,user=root] txn: bytes usage increases to 1.4 MiB (+1454080)
30660.307ms 0.348ms operation:dist sender
30660.322ms 0.015ms event:[client=10.142.15.204:47136,user=root,txn=779a7ccb,n1] querying next range at /Table/55/1/900/0
30660.374ms 0.051ms event:[client=10.142.15.204:47136,user=root,txn=779a7ccb,n1] r55510: sending batch 1 Put, 1 BeginTxn to (n11,s11):2
30660.387ms 0.013ms event:[client=10.142.15.204:47136,user=root,txn=779a7ccb,n1] sending request to alex-tpcc-0027:26257
30660.400ms 0.013ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:client txnID:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
30662.153ms 1.754ms operation:/cockroach.roachpb.Internal/Batch component:gRPC sb:1 span.kind:server txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
30662.190ms 0.036ms event:[n11] 1 Put, 1 BeginTxn
30662.208ms 0.018ms event:[n11,s11] executing 2 requests
30662.218ms 0.010ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
30662.229ms 0.012ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
30662.250ms 0.020ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for 1 overlapping requests
31041.007ms 378.758ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waited 378.752231ms for overlapping requests
31041.048ms 0.041ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
31041.878ms 0.830ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
31041.897ms 0.019ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] replica.Send got error: conflicting intents on /Table/55/1/900/0
31041.907ms 0.010ms event:[n11,s11] pushing 1 transaction(s)
31041.918ms 0.011ms operation:dist sender
31041.935ms 0.018ms event:[s11,n11] querying next range at /Table/55/1/900/0
31041.974ms 0.039ms event:[s11,n11] r55510: sending batch 1 PushTxn to (n11,s11):2
31041.994ms 0.020ms event:[s11,n11] sending request to local server
31042.012ms 0.018ms operation:/cockroach.roachpb.Internal/Batch
31042.018ms 0.006ms event:[n11] 1 PushTxn
31042.026ms 0.007ms event:[n11,s11] executing 1 requests
31042.039ms 0.013ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
31042.046ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
31042.065ms 0.018ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
31042.287ms 0.222ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
31046.025ms 3.738ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] replica.Send got error: failed to push "sql txn" id=9dd6fba5 key=/Table/55/1/900/0 rw=true pri=0.04616175 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527653725.190430123,1 orig=1527653712.440190569,0 max=1527653712.442074614,0 wto=false rop=false seq=8
31046.052ms 0.027ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] 779a7ccb pushing 9dd6fba5 (1 pending)
31046.061ms 0.008ms operation:[async] monitoring pusher txn sb:1 txnid:779a7ccb-5b5d-4a8c-8c02-33a5937f9510
31046.100ms 0.039ms operation:dist sender
31046.139ms 0.038ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
31046.166ms 0.028ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
31046.179ms 0.013ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
31046.192ms 0.013ms operation:/cockroach.roachpb.Internal/Batch
31046.197ms 0.005ms event:[n11] 1 QueryTxn
31046.203ms 0.006ms event:[n11,s11] executing 1 requests
31050.015ms 3.812ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] querying pushee
31050.031ms 0.016ms operation:dist sender
31050.051ms 0.020ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
31050.085ms 0.034ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
31050.104ms 0.019ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
31050.159ms 0.055ms operation:/cockroach.roachpb.Internal/Batch
31050.166ms 0.007ms event:[n11] 1 QueryTxn
31050.173ms 0.007ms event:[n11,s11] executing 1 requests
31050.181ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
31050.190ms 0.010ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
31050.198ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
31050.295ms 0.097ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
31096.639ms 46.344ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
31096.651ms 0.012ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
31096.660ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
31096.790ms 0.129ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
31096.841ms 0.052ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
31142.647ms 45.806ms operation:dist sender
31142.678ms 0.031ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
31142.742ms 0.064ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
31142.765ms 0.023ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
31142.784ms 0.019ms operation:/cockroach.roachpb.Internal/Batch
31142.792ms 0.009ms event:[n11] 1 QueryTxn
31142.799ms 0.007ms event:[n11,s11] executing 1 requests
31193.478ms 50.679ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
31193.489ms 0.011ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
31193.497ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
31193.596ms 0.100ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
31193.645ms 0.049ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
31307.160ms 113.514ms operation:dist sender
31307.200ms 0.041ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
31307.250ms 0.050ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
31307.272ms 0.022ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
31307.289ms 0.017ms operation:/cockroach.roachpb.Internal/Batch
31307.295ms 0.007ms event:[n11] 1 QueryTxn
31307.304ms 0.009ms event:[n11,s11] executing 1 requests
31357.989ms 50.685ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
31358.002ms 0.013ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
31358.010ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
31358.112ms 0.103ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
31358.184ms 0.071ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
31579.997ms 221.814ms operation:dist sender
31580.019ms 0.022ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
31580.058ms 0.039ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
31580.076ms 0.018ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
31580.094ms 0.018ms operation:/cockroach.roachpb.Internal/Batch
31580.103ms 0.009ms event:[n11] 1 QueryTxn
31580.109ms 0.006ms event:[n11,s11] executing 1 requests
31647.175ms 67.066ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
31784.479ms 137.304ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
31784.489ms 0.010ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
31784.581ms 0.092ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
31784.644ms 0.063ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
32198.495ms 413.851ms operation:dist sender
32198.521ms 0.026ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
32198.559ms 0.038ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
32198.577ms 0.018ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
32198.594ms 0.017ms operation:/cockroach.roachpb.Internal/Batch
32198.602ms 0.008ms event:[n11] 1 QueryTxn
32198.610ms 0.008ms event:[n11,s11] executing 1 requests
32250.452ms 51.842ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
32250.459ms 0.007ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
32250.465ms 0.006ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
32250.542ms 0.077ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
32250.579ms 0.038ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] no pusher found; backing off
32658.950ms 408.371ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] querying pushee
32658.963ms 0.013ms operation:dist sender
32658.985ms 0.023ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] querying next range at /Table/55/1/900/0
32659.025ms 0.040ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] r55510: sending batch 1 QueryTxn to (n11,s11):2
32659.044ms 0.019ms event:[s11,r55510/2:/Table/55/1/9{00-10},n11] sending request to local server
32659.062ms 0.018ms operation:/cockroach.roachpb.Internal/Batch
32659.068ms 0.006ms event:[n11] 1 QueryTxn
32659.077ms 0.009ms event:[n11,s11] executing 1 requests
32659.086ms 0.009ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-only path
32659.097ms 0.011ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
32659.104ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] waiting for read lock
32659.234ms 0.130ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read completed
32870.105ms 210.871ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] result of pending push: "sql txn" id=9dd6fba5 key=/Table/55/1/900/0 rw=true pri=0.04616175 iso=SERIALIZABLE stat=COMMITTED epo=1 ts=1527653729.328261809,0 orig=1527653729.328261809,0 max=1527653712.442074614,0 wto=false rop=false seq=21 int=5
32870.108ms 0.003ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] push request is satisfied
32870.202ms 0.094ms event:[n11,s11] 9dd6fba5-a6b2-445f-898a-05b96de4c6c7 is now COMMITTED
32870.207ms 0.005ms event:[n11,s11] resolving intents [wait=false]
32870.235ms 0.028ms operation:dist sender
32870.267ms 0.032ms event:[s11,n11] querying next range at /Table/55/1/900/0
32870.310ms 0.043ms event:[s11,n11] r55510: sending batch 1 ResolveIntent to (n11,s11):2
32870.330ms 0.021ms event:[s11,n11] sending request to local server
32870.365ms 0.034ms operation:/cockroach.roachpb.Internal/Batch
32870.371ms 0.006ms event:[n11] 1 ResolveIntent
32870.377ms 0.006ms event:[n11,s11] executing 1 requests
32870.386ms 0.008ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
32870.391ms 0.005ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
32870.404ms 0.013ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
32870.535ms 0.131ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
32870.565ms 0.030ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] read-write path
32870.576ms 0.011ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] command queue
32870.622ms 0.046ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applied timestamp cache
32870.915ms 0.293ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] evaluated request
32870.926ms 0.012ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] acquired {raft,replica}mu
33041.133ms 170.206ms event:[n11,s11,r55510/2:/Table/55/1/9{00-10}] applying command
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment