Skip to content

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

Closed
IslamAbdelRahman wants to merge 2 commits intofacebook:masterfrom
IslamAbdelRahman:log_file_line
Closed

Add macros to include file name and line number during Logging#1990
IslamAbdelRahman wants to merge 2 commits intofacebook:masterfrom
IslamAbdelRahman:log_file_line

Conversation

@IslamAbdelRahman
Copy link
Copy Markdown
Contributor

@IslamAbdelRahman IslamAbdelRahman commented Mar 14, 2017

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
Copy link
Copy Markdown
Contributor

facebook-github-bot commented Mar 14, 2017

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

@IslamAbdelRahman
Copy link
Copy Markdown
Contributor Author

IslamAbdelRahman commented Mar 14, 2017

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
Copy link
Copy Markdown
Contributor

facebook-github-bot commented Mar 14, 2017

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

@facebook-github-bot
Copy link
Copy Markdown
Contributor

facebook-github-bot commented Mar 14, 2017

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

@lightmark
Copy link
Copy Markdown
Contributor

lightmark commented Mar 15, 2017 •
edited
Loading

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

maysamyabandeh
maysamyabandeh approved these changes Mar 15, 2017
View reviewed changes
Copy link
Copy Markdown
Contributor

@maysamyabandeh maysamyabandeh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM (assuming that the tests pass)

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
Copy link
Copy Markdown
Contributor

@maysamyabandeh maysamyabandeh Mar 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why?

util/logging.h
#include "port/port.h"

// Helper macros that include information about file name and line number
#define STRINGIFY(x) #x
Copy link
Copy Markdown
Contributor

@maysamyabandeh maysamyabandeh Mar 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

util/logging.h
#define ROCKS_LOG_HEADER(LGR, FMT, ...) \
rocksdb::Log(InfoLogLevel::HEADER_LEVEL, LGR, FMT, ##__VA_ARGS__)

#define ROCKS_LOG_DEBUG(LGR, FMT, ...) \
Copy link
Copy Markdown
Contributor

@maysamyabandeh maysamyabandeh Mar 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Copy Markdown
Contributor Author

IslamAbdelRahman commented Mar 16, 2017

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@lightmark lightmark Awaiting requested review from lightmark

@siying siying Awaiting requested review from siying

1 more reviewer

@maysamyabandeh maysamyabandeh maysamyabandeh approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

CLA Signed

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@IslamAbdelRahman @facebook-github-bot @lightmark @maysamyabandeh