search

LLNL / umap

User-space Page Management
GNU Lesser General Public License v2.1
104 stars 22 forks source link

Logging: missing timestamp when timestamp logging is activated #117

Closed mweisgut closed 2 years ago

mweisgut commented 2 years ago

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?

https://github.com/LLNL/umap/blob/d9ea349200b5c948122ee23b989b6cb2ab3a188c/src/umap/util/Logger.cpp#L50-L73

IBPeng commented 2 years ago

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