recovery.py June 20, 2014
- John Ousterhout
Owned by John Ousterhout
=== Summary === Recovery time: 1.41 s Failure detection time: 0.33 s Recovery + detection time: 1.74 s Masters: 5 Backups: 10 Total nodes: 10 Replicas: 3 Objects per master: 592950.00 avg / 593336 max Object size: 1057.63 bytes avg / 1057.63 bytes max Total recovery segment entries: 2966625 Total live object space: 2990.34 MB Total recovery segment space w/ overhead: 2998.84 MB Storage type: disk Log directory: /home/ouster/.netbeans/remote/rcmaster.scs.stanford.edu/ouster2010-Windows-x86_64/C/Users/ouster/Documents/code/ramcloud/logs/20140620115504 === Coordinator Time === Total: 1406.70 ms / 99.48% Starting recovery on backups: 17.98 ms / 1.27% Starting recovery on masters: 0.27 ms / 0.02% Tablets recovered: 0.39 ms / 0.03% Completing recovery on backups: 0.04 ms / 0.00% Get table config: 5.73 ms / 0.41% Other: 1382.33 ms / 97.75% Receiving in transport: 1.48 ms / 0.10% === Recovery Master Time === Total (versus end-to-end recovery time): 1386.63 ms avg / 1388.79 ms max / 98.06% avg Total: 1386.63 ms avg / 1388.79 ms max / 100.00% avg Waiting for incoming segments: 316.87 ms avg / 462.98 ms max / 22.85% avg Inside recoverSegment: 983.57 ms avg / 1105.80 ms max / 70.93% avg Final log sync time: 11.19 ms avg / 12.44 ms max / 0.81% avg Removing tombstones: 0.00 ms / 0.00% Other: 75.00 ms avg / 81.74 ms max / 5.30% avg === Recovery Master recoverSegment Time === Total (versus end-to-end recovery time): 983.57 ms avg / 1105.80 ms max / 69.55% avg Total: 983.57 ms avg / 1105.80 ms max / 100.00% avg Managing replication: 32.18 ms avg / 37.50 ms max / 3.27% avg Verify checksum: 293.23 ms avg / 335.06 ms max / 29.81% avg Segment append: 309.31 ms avg / 337.81 ms max / 31.45% avg Other: 348.85 ms avg / 395.44 ms max / 35.47% avg === Recovery Master ReplicaManager Time during recoverSegment === Total (versus end-to-end recovery time): 32.18 ms avg / 37.50 ms max / 2.28% avg Total: 32.18 ms avg / 37.50 ms max / 100.00% avg Posting write RPCs for TX to transport: 12.04 ms avg / 15.29 ms max / 37.40% avg Other: 20.15 ms avg / 22.22 ms max / 62.60% avg === Recovery Master Stats === Final log sync amount: 22.83 MB avg / 21.60 MB min / 114.16 MB total Total replication amount: 2097.98 MB avg / 2095.33 MB min / 10489.88 MB total Total replication during replay: 2075.14 MB avg / 2071.97 MB min / 10375.72 MB total Opening sessions: 1.09 ms avg / 1.20 ms max / 0.08% avg Receiving in transport: 4.48 ms avg / 5.00 ms max / 0.32% avg Transmitting in transport: 118.81 ms avg / 125.36 ms max / 8.40% avg Client RPCs Active: 1317.01 ms avg / 1393.61 ms max / 93.13% avg Average GRD completion time: 11.73 ms avg / 12.11 ms max Log replication rate: 581.81 MB/s avg / 566.44 MB/s min / 2909.03 MB/s total Log replication rate during replay: 580.88 MB/s avg / 565.14 MB/s min / 2904.39 MB/s total Log replication rate during log sync: 684.16 MB/s avg / 579.00 MB/s min / 3420.81 MB/s total Replication: 1203.00 ms avg / 1234.86 ms max / 85.07% avg TX active: 1091.44 ms avg / 1121.85 ms max / 77.18% avg TX active during replication: 1091.19 ms avg / 1121.72 ms max / 90.71% avg TX active during replay: 1081.78 ms avg / 1110.13 ms max / 90.77% avg TX active during log sync: 9.41 ms avg / 11.60 ms max / 84.06% avg TX active rate during replication: 1923.54 MB/s avg / 1869.09 MB/s min / 9617.68 MB/s total TX active rate during replay: 1919.12 MB/s avg / 1869.16 MB/s min / 9595.60 MB/s total TX active rate during log sync: 2474.04 MB/s avg / 1862.48 MB/s min / 12370.21 MB/s total Copying for TX during replication: 115.32 ms avg / 120.74 ms max / 8.15% avg Copying for TX during replay: 115.31 ms avg / 120.74 ms max / 8.15% avg Copying for TX during log sync: 0.00 ms avg / 0.00 ms max / 0.00% avg Copying for tx during replication rate: 6068.06 MB/s avg / 5793.17 MB/s min / 30340.29 MB/s total Copying for TX during replay rate: 6002.13 MB/s avg / 5733.48 MB/s min / 30010.63 MB/s total Copying for TX during log sync rate: 3338903.52 MB/s avg / 1564744.12 MB/s min / 16694517.61 MB/s total Max active replication tasks: 3 tasks / 15 tasks total Memory read bandwidth used during replay: 4254.26 MB/s avg / 4185.62 MB/s min / 21271.29 MB/s total Memory write bandwidth used during replay: 3931.24 MB/s avg / 3807.28 MB/s min / 19656.18 MB/s total === Backup Time === RPC service time: 376.43 ms avg / 458.28 ms max / 26.62% avg startReadingData RPC: 0.34 ms avg / 0.77 ms max / 0.02% avg write RPC: 371.50 ms avg / 450.30 ms max / 26.27% avg Write copy: 369.21 ms avg / 447.65 ms max / 26.11% avg Other write RPC: 2.29 ms avg / 2.82 ms max / 0.16% avg getRecoveryData RPC: 3.50 ms avg / 11.75 ms max / 0.25% avg Other: 1.09 ms avg / 16.01 ms max / 0.08% avg Transmitting in transport: 108.84 ms avg / 125.36 ms max / 7.70% avg Filtering segments: 319.47 ms avg / 419.94 ms max / 22.59% avg Reading+filtering replicas: 1317.49 ms avg / 1385.89 ms max / 93.17% avg Reading replicas from disk: 1305.35 ms avg / 1372.73 ms max / 92.31% avg getRecoveryData completions: 187.50 avg / 190 max getRecoveryData retry fraction: 0.28 avg / 0.72 max === Efficiency === recoverSegment CPU: 2.62 ms avg Writing a segment: 0.73 ms avg Memory bandwidth (backup copies): 2.41 GB/s avg / 1.87 GB/s min === Network Utilization === Aggregate: 124.25 Gb/s / 49.70% Master in: 7.59 Gb/s avg / 7.16 Gb/s min / 37.95 Gb/s total Master out: 11.59 Gb/s avg / 11.58 Gb/s min / 57.97 Gb/s total Master out during replication: 13.64 Gb/s avg / 13.28 Gb/s min / 68.18 Gb/s total Master out during log sync: 16.04 Gb/s avg / 13.57 Gb/s min / 80.18 Gb/s total Backup in: 6.63 Gb/s avg / 5.30 Gb/s min / 66.28 Gb/s total Backup out: 6.63 Gb/s avg / 1.64 Gb/s min / 66.28 Gb/s total === Disk Utilization === Effective bandwidth: 226.29 MB/s avg / 214.98 MB/s min / 2262.93 MB/s total Active bandwidth: 227.81 MB/s avg / 217.54 MB/s min / 2278.05 MB/s total Active bandwidth reading: 229.46 MB/s avg / 215.63 MB/s min / 2294.60 MB/s total Active bandwidth writing: 231.96 MB/s avg / 163.90 MB/s min / 2319.56 MB/s total Disk active time: 99.33 % avg / 102.01 % max Disk reading time: 92.31 % avg / 97.07 % max Disk writing time: 7.02 % avg / 12.96 % max === Backup Events === Segments read: 37.40 avg / 38 max Primary segments loaded: 187.50 avg / 190 max Secondary segments loaded: 0 === Slowest Servers === Backup opens, writes: 192.168.1.104 / 348.8 ms Stalled reading segs from backups: 192.168.1.104 / 463.0 ms Reading from disk: 192.168.1.107 / 215.6 MB/s Writing to disk: 192.168.1.108 / 163.9 MB/s