You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@kudu.apache.org by "Will Berkeley (Code Review)" <ge...@cloudera.org> on 2019/01/18 01:42:41 UTC

[kudu-CR] Reduce MRS flush and rowset compaction logging 

Will Berkeley has uploaded this change for review. ( 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
---
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(-)



  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/34/12234/1
-- 
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: newchange
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change. ( http://gerrit.cloudera.org:8080/12234 )

Change subject: Reduce MRS flush and rowset compaction logging
......................................................................


Patch Set 2: Code-Review+2


-- 
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: comment
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Mitch Barnett <mb...@cloudera.com>
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Sat, 19 Jan 2019 00:00:19 +0000
Gerrit-HasComments: No

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change. ( http://gerrit.cloudera.org:8080/12234 )

Change subject: Reduce MRS flush and rowset compaction logging
......................................................................


Patch Set 2:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/12234/1//COMMIT_MSG
Commit Message:

http://gerrit.cloudera.org:8080/#/c/12234/1//COMMIT_MSG@75
PS1, Line 75: - bytes written
I didn't review the code yet, but was wondering whether we should also include bytes_read (for compactions). Or even some sort of aggregate that helps describe the distribution of bytes across the inputs.

The goal here is to figure out for a given compaction whether it was a "regular" one, or a "trickle of tiny DRS's" one. Do you think that would be useful?



-- 
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: comment
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Comment-Date: Fri, 18 Jan 2019 01:46:16 +0000
Gerrit-HasComments: Yes

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Hello Kudu Jenkins, 

I'd like you to reexamine a change. Please visit

    http://gerrit.cloudera.org:8080/12234

to look at the new patch set (#2).

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
---
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(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/34/12234/2
-- 
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: newpatchset
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Kudu Jenkins (120)

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
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 <wd...@gmail.com>
Reviewed-by: Adar Dembo <ad...@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 <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Mitch Barnett <mb...@cloudera.com>
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/12234 )

Change subject: Reduce MRS flush and rowset compaction logging
......................................................................


Patch Set 2: Verified+1

Unrelated flake.


-- 
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: comment
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Mitch Barnett <mb...@cloudera.com>
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Fri, 18 Jan 2019 04:59:09 +0000
Gerrit-HasComments: No

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/12234 )

Change subject: Reduce MRS flush and rowset compaction logging
......................................................................


Patch Set 1:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/12234/1//COMMIT_MSG
Commit Message:

http://gerrit.cloudera.org:8080/#/c/12234/1//COMMIT_MSG@75
PS1, Line 75: - bytes written
> I didn't review the code yet, but was wondering whether we should also incl
Yes. I am planning a follow up to add some information about the distribution of sizes of input rowsets. Since it will be the umpteenth time I am adding a 5-number summary somewhere in Kudu, I wanted to make a precursor patch to add a little class to calculate 5-number summaries, then use that to summarize the messages like the ones from compaction.cc:917 above.

Actually, the idea occurs to me that I might be able to reuse some existing histogram code too.



-- 
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: comment
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Fri, 18 Jan 2019 02:04:09 +0000
Gerrit-HasComments: Yes

[kudu-CR] Reduce MRS flush and rowset compaction logging

Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has removed a vote on this change.

Change subject: Reduce MRS flush and rowset compaction logging
......................................................................


Removed Verified-1 by Kudu Jenkins (120)
-- 
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: deleteVote
Gerrit-Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
Gerrit-Change-Number: 12234
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Mitch Barnett <mb...@cloudera.com>
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>