Will Berkeley has submitted this change and it was merged. (
http://gerrit.cloudera.org:8080/12234 )
Change subject: Reduce MRS flush and rowset compaction logging
......................................................................
Reduce MRS flush and rowset compaction logging
MRS flushes and rowset compaction (which share much of the same code)
are both very verbose. Here's an example of a large rowset compaction:
I0113 21:55:44.541332 67917 maintenance_manager.cc:302] P
0fe9d23b0e9c49f1af1b1095bfd395fb: Scheduling
CompactRowSetsOp(be6681dcfc7a41dca7268c71f7d9bd21): perf score=0.604064
I0113 21:55:44.543792 63804 tablet.cc:1664] T be6681dcfc7a41dca7268c71f7d9bd21
P 0fe9d23b0e9c49f1af1b1095bfd395fb: Compaction: stage 1 complete, picked 46
rowsets to compact or flush
I0113 21:55:44.543824 63804 compaction.cc:914] Selected 46 rowsets to compact:
I0113 21:55:44.543833 63804 compaction.cc:917] RowSet(50276)(current size on
disk: ~9737 bytes)
I0113 21:55:44.543840 63804 compaction.cc:917] RowSet(50277)(current size on
disk: ~9229 bytes)
I0113 21:55:44.543848 63804 compaction.cc:917] RowSet(50331)(current size on
disk: ~9723 bytes)
I0113 21:55:44.543854 63804 compaction.cc:917] RowSet(50333)(current size on
disk: ~9226 bytes)
I0113 21:55:44.543860 63804 compaction.cc:917] RowSet(50359)(current size on
disk: ~9196 bytes)
I0113 21:55:44.543866 63804 compaction.cc:917] RowSet(50360)(current size on
disk: ~9815 bytes)
I0113 21:55:44.543874 63804 compaction.cc:917] RowSet(50366)(current size on
disk: ~9718 bytes)
I0113 21:55:44.543885 63804 compaction.cc:917] RowSet(50367)(current size on
disk: ~9184 bytes)
I0113 21:55:44.543892 63804 compaction.cc:917] RowSet(50368)(current size on
disk: ~9161 bytes)
I0113 21:55:44.543898 63804 compaction.cc:917] RowSet(50407)(current size on
disk: ~9184 bytes)
I0113 21:55:44.543905 63804 compaction.cc:917] RowSet(50409)(current size on
disk: ~9178 bytes)
I0113 21:55:44.543910 63804 compaction.cc:917] RowSet(50410)(current size on
disk: ~9165 bytes)
I0113 21:55:44.543917 63804 compaction.cc:917] RowSet(50412)(current size on
disk: ~9825 bytes)
I0113 21:55:44.543923 63804 compaction.cc:917] RowSet(50413)(current size on
disk: ~9162 bytes)
I0113 21:55:44.543931 63804 compaction.cc:917] RowSet(50420)(current size on
disk: ~9175 bytes)
I0113 21:55:44.543942 63804 compaction.cc:917] RowSet(50421)(current size on
disk: ~9821 bytes)
I0113 21:55:44.543953 63804 compaction.cc:917] RowSet(50422)(current size on
disk: ~9215 bytes)
I0113 21:55:44.543962 63804 compaction.cc:917] RowSet(50424)(current size on
disk: ~9234 bytes)
I0113 21:55:44.543972 63804 compaction.cc:917] RowSet(50429)(current size on
disk: ~9179 bytes)
I0113 21:55:44.543982 63804 compaction.cc:917] RowSet(50430)(current size on
disk: ~9209 bytes)
I0113 21:55:44.543999 63804 compaction.cc:917] RowSet(50432)(current size on
disk: ~9206 bytes)
I0113 21:55:44.544008 63804 compaction.cc:917] RowSet(50433)(current size on
disk: ~9194 bytes)
I0113 21:55:44.544018 63804 compaction.cc:917] RowSet(50434)(current size on
disk: ~9157 bytes)
I0113 21:55:44.544026 63804 compaction.cc:917] RowSet(50435)(current size on
disk: ~9201 bytes)
I0113 21:55:44.544036 63804 compaction.cc:917] RowSet(50436)(current size on
disk: ~9155 bytes)
I0113 21:55:44.544044 63804 compaction.cc:917] RowSet(50461)(current size on
disk: ~9260 bytes)
I0113 21:55:44.544054 63804 compaction.cc:917] RowSet(50465)(current size on
disk: ~9179 bytes)
I0113 21:55:44.544064 63804 compaction.cc:917] RowSet(50468)(current size on
disk: ~9263 bytes)
I0113 21:55:44.544070 63804 compaction.cc:917] RowSet(50473)(current size on
disk: ~9232 bytes)
I0113 21:55:44.544077 63804 compaction.cc:917] RowSet(50500)(current size on
disk: ~9228 bytes)
I0113 21:55:44.544083 63804 compaction.cc:917] RowSet(50502)(current size on
disk: ~9247 bytes)
I0113 21:55:44.544092 63804 compaction.cc:917] RowSet(50527)(current size on
disk: ~9250 bytes)
I0113 21:55:44.544100 63804 compaction.cc:917] RowSet(50533)(current size on
disk: ~9240 bytes)
I0113 21:55:44.544109 63804 compaction.cc:917] RowSet(50540)(current size on
disk: ~35746907 bytes)
I0113 21:55:44.544121 63804 compaction.cc:917] RowSet(50541)(current size on
disk: ~35630515 bytes)
I0113 21:55:44.544131 63804 compaction.cc:917] RowSet(50542)(current size on
disk: ~23027388 bytes)
I0113 21:55:44.544142 63804 compaction.cc:917] RowSet(50545)(current size on
disk: ~9911 bytes)
I0113 21:55:44.544148 63804 compaction.cc:917] RowSet(50548)(current size on
disk: ~9267 bytes)
I0113 21:55:44.544158 63804 compaction.cc:917] RowSet(50549)(current size on
disk: ~10061 bytes)
I0113 21:55:44.544168 63804 compaction.cc:917] RowSet(50550)(current size on
disk: ~9256 bytes)
I0113 21:55:44.544174 63804 compaction.cc:917] RowSet(50559)(current size on
disk: ~9847 bytes)
I0113 21:55:44.544183 63804 compaction.cc:917] RowSet(50576)(current size on
disk: ~9265 bytes)
I0113 21:55:44.544189 63804 compaction.cc:917] RowSet(50587)(current size on
disk: ~9856 bytes)
I0113 21:55:44.544198 63804 compaction.cc:917] RowSet(50588)(current size on
disk: ~10762 bytes)
I0113 21:55:44.544206 63804 compaction.cc:917] RowSet(50589)(current size on
disk: ~10064 bytes)
I0113 21:55:44.544216 63804 compaction.cc:917] RowSet(50592)(current size on
disk: ~10108 bytes)
I0113 21:55:44.544230 63804 tablet.cc:1444] T be6681dcfc7a41dca7268c71f7d9bd21
P 0fe9d23b0e9c49f1af1b1095bfd395fb: Compaction: entering phase 1 (flushing
snapshot). Phase 1 snapshot: MvccSnapshot[committed={T|T < 6338306555103207424
or (T in {6338306555103207424})}]
I0113 21:55:44.548666 63804 multi_column_writer.cc:98] Opened CFile writers for
35 column(s)
I0113 21:55:45.577991 63804 multi_column_writer.cc:98] Opened CFile writers for
35 column(s)
I0113 21:55:46.560835 63804 multi_column_writer.cc:98] Opened CFile writers for
35 column(s)
I0113 21:55:47.150137 63804 tablet.cc:1529] T be6681dcfc7a41dca7268c71f7d9bd21
P 0fe9d23b0e9c49f1af1b1095bfd395fb: Compaction: entering phase 2 (starting to
duplicate updates in new rowsets)
I0113 21:55:47.151619 63804 tablet.cc:1584] T be6681dcfc7a41dca7268c71f7d9bd21
P 0fe9d23b0e9c49f1af1b1095bfd395fb: Compaction Phase 2: carrying over any
updates which arrived during Phase 1
I0113 21:55:47.151638 63804 tablet.cc:1586] T be6681dcfc7a41dca7268c71f7d9bd21
P 0fe9d23b0e9c49f1af1b1095bfd395fb: Phase 2 snapshot:
MvccSnapshot[committed={T|T < 6338306555103207424 or (T in
{6338306555103207424})}]
I0113 21:55:47.625000 63804 tablet.cc:1634] T be6681dcfc7a41dca7268c71f7d9bd21
P 0fe9d23b0e9c49f1af1b1095bfd395fb: Compaction successful on 1609240 rows
(94320404 bytes)
I0113 21:55:47.631129 63804 maintenance_manager.cc:492] P
0fe9d23b0e9c49f1af1b1095bfd395fb:
CompactRowSetsOp(be6681dcfc7a41dca7268c71f7d9bd21) complete. Timing: real
3.090s user 2.770s sys 0.284s Metrics:
{"cfile_cache_hit":2680,"cfile_cache_hit_bytes":8010765,"cfile_cache_miss":7724,"cfile_cache_miss_bytes":173275793,"cfile_init":1578,"data
dirs.queue_time_us":72960,"data dirs.run_cpu_time_us":2593,"data
dirs.run_wall_time_us":3285,"delta_iterators_relevant":32,"fdatasync":83,"fdatasync_us":13216,"lbm_read_time_us":85542,"lbm_reads_lt_1ms":14036,"lbm_write_time_us":72827,"lbm_writes_lt_1ms":2430,"mutex_wait_us":68,"spinlock_wait_cycles":37888,"thread_start_us":191,"threads_started":6,"wal-append.queue_time_us":69}
Yikes. This patch moves the fluff in the middle to VLOG(1), and adds
some trace metrics to provide useful information that's in the fluff.
Namely,
- bytes written
- rows_written
- number of input rowsets for a rowset compaction
- number of output diskrowsets
Here's how an MRS flush looks now:
I0117 17:31:10.059830 200036352 maintenance_manager.cc:304] P
92c6463ad225421797bbb02aedbe6d8e: Scheduling
FlushMRSOp(dc75a0b793c44a52b40a642de6d0f260): perf score=0.033403
I0117 17:31:10.067961 141012992 maintenance_manager.cc:494] P
92c6463ad225421797bbb02aedbe6d8e: FlushMRSOp(dc75a0b793c44a52b40a642de6d0f260)
complete. Timing: real 0.008s user 0.005s sys 0.003s Metrics:
{"bytes_written":13462,"cfile_init":1,"drs_written":1,"fdatasync":6,"fdatasync_us":560,"rows_written":235,"thread_start_us":68,"threads_started":1,"wal-append.queue_time_us":115}
Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Reviewed-on: http://gerrit.cloudera.org:8080/12234
Tested-by: Will Berkeley <wdberke...@gmail.com>
Reviewed-by: Adar Dembo <a...@cloudera.com>
---
M src/kudu/tablet/compaction.cc
M src/kudu/tablet/multi_column_writer.cc
M src/kudu/tablet/tablet.cc
3 files changed, 39 insertions(+), 23 deletions(-)
Approvals:
Will Berkeley: Verified
Adar Dembo: Looks good to me, approved
--
To view, visit http://gerrit.cloudera.org:8080/12234
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 3
Gerrit-Owner: Will Berkeley <wdberke...@gmail.com>
Gerrit-Reviewer: Adar Dembo <a...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Mitch Barnett <mbarn...@cloudera.com>
Gerrit-Reviewer: Will Berkeley <wdberke...@gmail.com>
