Add macros to include file name and line number during Logging #1990

IslamAbdelRahman · 2017-03-14T21:23:18Z

current logging

2017/03/14-14:20:30.393432 7fedde9f5700 (Original Log Time 2017/03/14-14:20:30.393414) [default] Level summary: base level 1 max bytes base 268435456 files[1 0 0 0 0 0 0] max score 0.25
2017/03/14-14:20:30.393438 7fedde9f5700 [JOB 2] Try to delete WAL files size 61417909, prev total WAL file size 73820858, number of live WAL files 2.
2017/03/14-14:20:30.393464 7fedde9f5700 [DEBUG] [JOB 2] Delete /dev/shm/old_logging//MANIFEST-000001 type=3 #1 -- OK
2017/03/14-14:20:30.393472 7fedde9f5700 [DEBUG] [JOB 2] Delete /dev/shm/old_logging//000003.log type=0 #3 -- OK
2017/03/14-14:20:31.427103 7fedd49f1700 [default] New memtable created with log file: #9. Immutable memtables: 0.
2017/03/14-14:20:31.427179 7fedde9f5700 [JOB 3] Syncing log #6
2017/03/14-14:20:31.427190 7fedde9f5700 (Original Log Time 2017/03/14-14:20:31.427170) Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots allowed 1, compaction slots scheduled 1
2017/03/14-14:20:31.427194 7fedde9f5700 [default] [JOB 3] Flushing memtable with next log file: 9
2017/03/14-14:20:31.427215 7fedde9f5700 EVENT_LOG_v1 {"time_micros": 1489526431427207, "job": 3, "event": "flush_started", "num_memtables": 1, "num_entries": 468860, "num_deletes": 0, "memory_usage": 65014064}
2017/03/14-14:20:31.427219 7fedde9f5700 [default] [JOB 3] Level-0 flush table #10: started
2017/03/14-14:20:31.701804 7fedde9f5700 EVENT_LOG_v1 {"time_micros": 1489526431701781, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 10, "file_size": 31690882, "table_properties": {"data_size": 31471306, "index_size": 411022, "filter_size": 0, "raw_key_size": 11252640, "raw_average_key_size": 24, "raw_value_size": 46886000, "raw_average_value_size": 100, "num_data_blocks": 14208, "num_entries": 468860, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2017/03/14-14:20:31.701820 7fedde9f5700 [default] [JOB 3] Level-0 flush table #10: 31690882 bytes OK
2017/03/14-14:20:31.701907 7fedde9f5700 (Original Log Time 2017/03/14-14:20:31.701832) [default] Level-0 commit table #10 started
2017/03/14-14:20:31.701910 7fedde9f5700 (Original Log Time 2017/03/14-14:20:31.701873) [default] Level-0 commit table #10: memtable #1 done
2017/03/14-14:20:31.701912 7fedde9f5700 (Original Log Time 2017/03/14-14:20:31.701881) EVENT_LOG_v1 {"time_micros": 1489526431701876, "job": 3, "event": "flush_finished", "lsm_state": [2, 0, 0, 0, 0, 0, 0], "immutable_memtables": 0}
2017/03/14-14:20:31.701913 7fedde9f5700 (Original Log Time 2017/03/14-14:20:31.701897) [default] Level summary: base level 1 max bytes base 268435456 files[2 0 0 0 0 0 0] max score 0.50
2017/03/14-14:20:31.701918 7fedde9f5700 [JOB 3] Try to delete WAL files size 61420660, prev total WAL file size 69582091, number of live WAL files 2.
2017/03/14-14:20:31.701933 7fedde9f5700 [DEBUG] [JOB 3] Delete /dev/shm/old_logging//000006.log type=0 #6 -- OK
2017/03/14-14:20:31.822164 7fede55869c0 Shutdown: canceling all background work
2017/03/14-14:20:31.829494 7fede55869c0 Shutdown complete

new logging

2017/03/14-14:20:37.018909 7fd71dff5700 (Original Log Time 2017/03/14-14:20:37.018888) [db/db_impl.cc:1956] [default] Level summary: base level 1 max bytes base 268435456 files[1 0 0 0 0 0 0] max score 0.25
2017/03/14-14:20:37.018915 7fd71dff5700 [db/db_impl.cc:1047] [JOB 2] Try to delete WAL files size 61418171, prev total WAL file size 74252110, number of live WAL files 2.
2017/03/14-14:20:37.018930 7fd71dff5700 [DEBUG] [db/db_impl.cc:966] [JOB 2] Delete /dev/shm/new_logging//MANIFEST-000001 type=3 #1 -- OK
2017/03/14-14:20:37.018937 7fd71dff5700 [DEBUG] [db/db_impl.cc:966] [JOB 2] Delete /dev/shm/new_logging//000003.log type=0 #3 -- OK
2017/03/14-14:20:38.070707 7fd713ff1700 [db/db_impl.cc:5288] [default] New memtable created with log file: #9. Immutable memtables: 0.
2017/03/14-14:20:38.070847 7fd71dff5700 [db/db_impl.cc:1879] [JOB 3] Syncing log #6
2017/03/14-14:20:38.070865 7fd71dff5700 (Original Log Time 2017/03/14-14:20:38.070830) [db/db_impl.cc:3252] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots allowed 1, compaction slots scheduled 1
2017/03/14-14:20:38.070868 7fd71dff5700 [db/flush_job.cc:264] [default] [JOB 3] Flushing memtable with next log file: 9
2017/03/14-14:20:38.070892 7fd71dff5700 EVENT_LOG_v1 {"time_micros": 1489526438070882, "job": 3, "event": "flush_started", "num_memtables": 1, "num_entries": 468869, "num_deletes": 0, "memory_usage": 65014048}
2017/03/14-14:20:38.070896 7fd71dff5700 [db/flush_job.cc:293] [default] [JOB 3] Level-0 flush table #10: started
2017/03/14-14:20:38.352703 7fd71dff5700 EVENT_LOG_v1 {"time_micros": 1489526438352679, "cf_name": "default", "job": 3, "event": "table_file_creation", "file_number": 10, "file_size": 31691577, "table_properties": {"data_size": 31471966, "index_size": 411052, "filter_size": 0, "raw_key_size": 11252856, "raw_average_key_size": 24, "raw_value_size": 46886900, "raw_average_value_size": 100, "num_data_blocks": 14209, "num_entries": 468869, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2017/03/14-14:20:38.352721 7fd71dff5700 [db/flush_job.cc:317] [default] [JOB 3] Level-0 flush table #10: 31691577 bytes OK
2017/03/14-14:20:38.352833 7fd71dff5700 (Original Log Time 2017/03/14-14:20:38.352743) [db/memtable_list.cc:360] [default] Level-0 commit table #10 started
2017/03/14-14:20:38.352836 7fd71dff5700 (Original Log Time 2017/03/14-14:20:38.352792) [db/memtable_list.cc:383] [default] Level-0 commit table #10: memtable #1 done
2017/03/14-14:20:38.352837 7fd71dff5700 (Original Log Time 2017/03/14-14:20:38.352802) EVENT_LOG_v1 {"time_micros": 1489526438352796, "job": 3, "event": "flush_finished", "lsm_state": [2, 0, 0, 0, 0, 0, 0], "immutable_memtables": 0}
2017/03/14-14:20:38.352839 7fd71dff5700 (Original Log Time 2017/03/14-14:20:38.352820) [db/db_impl.cc:1956] [default] Level summary: base level 1 max bytes base 268435456 files[2 0 0 0 0 0 0] max score 0.50
2017/03/14-14:20:38.352845 7fd71dff5700 [db/db_impl.cc:1047] [JOB 3] Try to delete WAL files size 61421839, prev total WAL file size 69581829, number of live WAL files 2.
2017/03/14-14:20:38.352860 7fd71dff5700 [DEBUG] [db/db_impl.cc:966] [JOB 3] Delete /dev/shm/new_logging//000006.log type=0 #6 -- OK
2017/03/14-14:20:38.453229 7fd724a719c0 [db/db_impl.cc:392] Shutdown: canceling all background work
2017/03/14-14:20:38.459462 7fd724a719c0 [db/db_impl.cc:518] Shutdown complete

facebook-github-bot · 2017-03-14T21:24:46Z

@IslamAbdelRahman has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

IslamAbdelRahman · 2017-03-14T21:25:53Z

macros exist in https://github.com/facebook/rocksdb/pull/1990/files#diff-4e3ab62cad64d4929b71457f9c8dad08

almost all the changes are update the code to use the new macros

facebook-github-bot · 2017-03-14T21:28:28Z

@IslamAbdelRahman updated the pull request - view changes - changes since last import

facebook-github-bot · 2017-03-14T21:32:12Z

@IslamAbdelRahman has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

lightmark · 2017-03-15T01:59:11Z

I perfer to put filename:line always first. Currently the log seems not aligned and hard to spot it.

maysamyabandeh

LGTM (assuming that the tests pass)

maysamyabandeh · 2017-03-15T03:02:39Z

util/logging.h

+#define TOSTRING(x) STRINGIFY(x)
+#define PREPEND_FILE_LINE(FMT) ("[" __FILE__ ":" TOSTRING(__LINE__) "] " FMT)
+
+// Don't inclide file/line info in HEADER level


maysamyabandeh · 2017-03-15T03:05:09Z

util/logging.h

@@ -16,6 +16,42 @@
 #include <string>
 #include "port/port.h"

+// Helper macros that include information about file name and line number
+#define STRINGIFY(x) #x


Can we add ROCKS_ prefix to these macros just in case customers also using them?

maysamyabandeh · 2017-03-15T03:39:43Z

util/logging.h

+#define ROCKS_LOG_HEADER(LGR, FMT, ...) \
+  rocksdb::Log(InfoLogLevel::HEADER_LEVEL, LGR, FMT, ##__VA_ARGS__)
+
+#define ROCKS_LOG_DEBUG(LGR, FMT, ...)                                 \


This provide an optimization opportunity: later we can redefine some of these macros to be null in production. For example if we redefine ROCKS_LOG_DEBUG to null when DEBUG_LEVEL is 0, then we save the cost of function call.

IslamAbdelRahman · 2017-03-16T02:21:07Z

@lightmark unfortunately it won't be very easy to do that (it's possible but it means that we will need to to it in runtime, instead of in compile time like in this PR)

Add handy macros to include file name and ling number during Logging

11422db

facebook-github-bot added the CLA Signed label Mar 14, 2017

IslamAbdelRahman requested review from maysamyabandeh, lightmark and siying March 14, 2017 21:24

minor changes to auto_roll_logger_test

4ade223

maysamyabandeh approved these changes Mar 15, 2017

View reviewed changes

facebook-github-bot closed this in e191636 Mar 16, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add macros to include file name and line number during Logging #1990

Add macros to include file name and line number during Logging #1990

IslamAbdelRahman commented Mar 14, 2017

facebook-github-bot commented Mar 14, 2017

IslamAbdelRahman commented Mar 14, 2017

facebook-github-bot commented Mar 14, 2017

facebook-github-bot commented Mar 14, 2017

lightmark commented Mar 15, 2017 •

edited

Loading

maysamyabandeh left a comment

maysamyabandeh Mar 15, 2017

maysamyabandeh Mar 15, 2017

maysamyabandeh Mar 15, 2017

IslamAbdelRahman commented Mar 16, 2017

Add macros to include file name and line number during Logging #1990

Add macros to include file name and line number during Logging #1990

Conversation

IslamAbdelRahman commented Mar 14, 2017

facebook-github-bot commented Mar 14, 2017

IslamAbdelRahman commented Mar 14, 2017

facebook-github-bot commented Mar 14, 2017

facebook-github-bot commented Mar 14, 2017

lightmark commented Mar 15, 2017 • edited Loading

maysamyabandeh left a comment

Choose a reason for hiding this comment

maysamyabandeh Mar 15, 2017

Choose a reason for hiding this comment

maysamyabandeh Mar 15, 2017

Choose a reason for hiding this comment

maysamyabandeh Mar 15, 2017

Choose a reason for hiding this comment

IslamAbdelRahman commented Mar 16, 2017

lightmark commented Mar 15, 2017 •

edited

Loading