Logging: missing timestamp when timestamp logging is activated

[mweisgut]

With UMAP_LOG_LEVEL=DEBUG and UMAP_LOG_NO_TIMESTAMP_LEVEL not being set, I tried to activate the debug logging with timestamps. The resulting logs, however, do not contain a timestamp:

1200130:1200130 [DEBUG][../src/umap/umap.cpp:30]: umap region_addr: 0, region_size: 68719476736, prot: 3, flags: 2, offset: 0
1200130:1200130 [DEBUG][../src/umap/RegionManager.cpp:232]: set_umap_page_size Adjusting page size from 0 to 1048576
1200130:1200130 [DEBUG][../src/umap/RegionManager.cpp:208]: set_max_pages_in_buffer Maximum pages in page buffer changed from 0 to 410 pages
1200130:1200130 [INFO][../src/umap/umap.cpp:138]: umap_ex region_addr: 0, region_size: 68719476736, prot: 3, flags: 2, offset: 0, store: 0, umap_psize: 1048576
1200130:1200130 [DEBUG][../src/umap/store/StoreFile.cpp:21]: StoreFile region: 0x7fc46b700000 rsize: 68719476736 alignsize: 1048576 fd: 3
1200130:1200130 [DEBUG][../src/umap/RegionManager.cpp:43]: addRegion No active regions, initializing engine
1200130:1200130 [DEBUG][../src/umap/Uffd.cpp:147]: Uffd
 maximum fault events: 256
            page size: 1048576
1200130:1200130 [DEBUG][../src/umap/WorkerPool.hpp:73]: start_thread_pool Starting Uffd Manager Pool of 1 threads
1200130:1200130 [DEBUG][../src/umap/WorkerPool.hpp:73]: start_thread_pool Starting Fill Workers Pool of 1 threads
1200130:1200130 [DEBUG][../src/umap/WorkerPool.hpp:73]: start_thread_pool Starting Evict Workers Pool of 1 threads
1200130:1200130 [DEBUG][../src/umap/WorkerPool.hpp:73]: start_thread_pool Starting Evict Manager Pool of 1 threads
1200130:1200130 [DEBUG][../src/umap/RegionManager.cpp:53]: addRegion region: 0x7fc46b700000 - 0x7fd46b700000, region_size: 68719476736, number of regions: 2
1200130:1200130 [DEBUG][../src/umap/Uffd.cpp:259]: register_region Registering 65536 pages from: 0x7fc46b700000 - 0x7fd46b6fffff
1200130:1200187 [DEBUG][../src/umap/Buffer.cpp:214]: process_page_event NEW: { 0x7fc46b700000, FILLING, DIRTY } From: { m_size: 410, m_waits_for_avail_pd: 0, m_present_pages.size():  1, m_free_pages.size(): 409, m_busy_pages.size():  1 }
1200130:1200188 [DEBUG][../src/umap/FillWorkers.cpp:42]: FillWorker : { page_desc: { 0x7fc46b700000, FILLING, DIRTY }, type: NONE } { m_size: 410, m_waits_for_avail_pd: 0, m_present_pages.size():  1, m_free_pages.size(): 409, m_busy_pages.size():  1 }
1200130:1200188 [DEBUG][../src/umap/store/StoreFile.cpp:30]: read_from_store pread(fd=3, buf=0x7fd857b00000, nb=1048576, off=0)
1200130:1200187 [DEBUG][../src/umap/Buffer.cpp:214]: process_page_event NEW: { 0x7fc46b900000, FILLING, DIRTY } From: { m_size: 410, m_waits_for_avail_pd: 0, m_present_pages.size():  2, m_free_pages.size(): 408, m_busy_pages.size():  2 }
1200130:1200188 [DEBUG][../src/umap/FillWorkers.cpp:42]: FillWorker : { page_desc: { 0x7fc46b900000, FILLING, DIRTY }, type: NONE } { m_size: 410, m_waits_for_avail_pd: 0, m_present_pages.size():  2, m_free_pages.size(): 408, m_busy_pages.size():  2 }
1200130:1200188 [DEBUG][../src/umap/store/StoreFile.cpp:30]: read_from_store pread(fd=3, buf=0x7fd857b00000, nb=1048576, off=2097152)
1200130:1200187 [DEBUG][../src/umap/Buffer.cpp:214]: process_page_event NEW: { 0x7fc46ba00000, FILLING, DIRTY } From: { m_size: 410, m_waits_for_avail_pd: 0, m_present_pages.size():  3, m_free_pages.size(): 407, m_busy_pages.size():  3 }
1200130:1200188 [DEBUG][../src/umap/FillWorkers.cpp:42]: FillWorker : { page_desc: { 0x7fc46ba00000, FILLING, DIRTY }, type: NONE } { m_size: 410, m_waits_for_avail_pd: 0, m_present_pages.size():  3, m_free_pages.size(): 407, m_busy_pages.size():  3 }
1200130:1200188 [DEBUG][../src/umap/store/StoreFile.cpp:30]: read_from_store pread(fd=3, buf=0x7fd857b00000, nb=1048576, off=3145728)

If I understand the code correctly, no timestamps are written into the log messages, even if m_log_timestamp is true, aren't they?

umap/src/umap/util/Logger.cpp

Lines 50 to 73 in d9ea349

	void Logger::logMessage( message::Level level,
	const std::string& message,
	const std::string& fileName,
	int line ) noexcept
	{
	if ( !logLevelEnabled( level ) )
	return; /* short-circuit */
	std::lock_guard<std::mutex> guard(g_logging_mutex);
	if (m_log_timestamp) {
	std::cout
	<< getpid() << ":"
	<< syscall(__NR_gettid) << " "
	<< "[" << MessageLevelName[ level ] << "]"
	<< "[" << fileName << ":" << line << "]:"
	<< message
	<< std::endl;
	}
	else {
	std::cout
	<< message
	<< std::endl;
	}
	}

[IBPeng]

Thank you for reporting. The timestamp information has now been added to logs.