single-cell-data / TileDB-SOMA

Python and R SOMA APIs using TileDB’s cloud-native format. Ideal for single-cell data at any scale.
https://tiledbsoma.readthedocs.io
MIT License
90 stars 25 forks source link

[c++] Support option to set log level from environment #2972

Closed johnkerl closed 1 month ago

johnkerl commented 1 month ago

I find this very useful, particularly on #2407 / [sc-51048]. If useful to other folks, great; if not, hopefully not too disruptive.

codecov[bot] commented 1 month ago

Codecov Report

All modified and coverable lines are covered by tests :white_check_mark:

Project coverage is 89.99%. Comparing base (7cacee1) to head (16e7cdb). Report is 3 commits behind head on main.

Additional details and impacted files ```diff @@ Coverage Diff @@ ## main #2972 +/- ## ========================================== + Coverage 89.84% 89.99% +0.14% ========================================== Files 39 39 Lines 4057 4057 ========================================== + Hits 3645 3651 +6 + Misses 412 406 -6 ``` | [Flag](https://app.codecov.io/gh/single-cell-data/TileDB-SOMA/pull/2972/flags?src=pr&el=flags&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=single-cell-data) | Coverage Δ | | |---|---|---| | [python](https://app.codecov.io/gh/single-cell-data/TileDB-SOMA/pull/2972/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=single-cell-data) | `89.99% <ø> (+0.14%)` | :arrow_up: | Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=single-cell-data#carryforward-flags-in-the-pull-request-comment) to find out more. | [Components](https://app.codecov.io/gh/single-cell-data/TileDB-SOMA/pull/2972/components?src=pr&el=components&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=single-cell-data) | Coverage Δ | | |---|---|---| | [python_api](https://app.codecov.io/gh/single-cell-data/TileDB-SOMA/pull/2972/components?src=pr&el=component&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=single-cell-data) | `89.99% <ø> (+0.14%)` | :arrow_up: | | [libtiledbsoma](https://app.codecov.io/gh/single-cell-data/TileDB-SOMA/pull/2972/components?src=pr&el=component&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=single-cell-data) | `∅ <ø> (∅)` | |
nguyenv commented 1 month ago

Is this something we should add to CMakeLists.txt too where we default it to OFF? Maybe for debug builds it could be INFO.

eddelbuettel commented 1 month ago

It's is strictly run-time (once compiled in). spdlog takes care of it. Using the (zero-other-dependency) example program I used before (included below). We should be able to tuck this away in the non-public part of the logger.

As it has a marginal cost (of checking a run-time condition) you could tuck it inside #if .. #endif for debug mode. But if would loose the benefit of 'always being there' without mods to code which is, if I understand it correctly, @johnkerl is after here (and which I also find appealing).

$ g++ -std=c++17 spdlog_ex_headeronly.cpp -o spdlog_ex_headeronly
$ ./spdlog_ex_headeronly    # no setting
[14:26:53.559466] [my_demo] [I] [thread 2308290] Welcome to spdlog!
[14:26:53.559523] [my_demo] [E] [thread 2308290] Some error message with arg: 1
[14:26:53.559539] [my_demo] [I] [thread 2308290] Elapsed time: 6.8161e-05
[14:26:53.559548] [my_demo] [W] [thread 2308290] Easy padding in numbers like 00000012
[14:26:53.559584] [my_demo] [C] [thread 2308290] Support for int: 42;  hex: 2a;  oct: 52; bin: 101010
[14:26:53.559600] [my_demo] [I] [thread 2308290] Support for floats 1.23
[14:26:53.559612] [my_demo] [I] [thread 2308290] Positional args are supported too..
[14:26:53.559622] [my_demo] [I] [thread 2308290] left aligned                  
[14:26:53.559631] [my_demo] [I] [thread 2308290] Elapsed time: 0.000164105
$
$ SPDLOG_LEVEL=critical ./spdlog_ex_headeronly    # critical only
[14:27:04.225658] [my_demo] [C] [thread 2308818] Support for int: 42;  hex: 2a;  oct: 52; bin: 101010
$ 
$ SPDLOG_LEVEL=error ./spdlog_ex_headeronly    # error or higher
[14:27:15.571203] [my_demo] [E] [thread 2309374] Some error message with arg: 1
[14:27:15.571263] [my_demo] [C] [thread 2309374] Support for int: 42;  hex: 2a;  oct: 52; bin: 101010
$ 

It is activated by calling one line as demonstrated eg here and shown in the example I compiled and use here.

```c++ #define FMT_HEADER_ONLY #define SPDLOG_HEADER_ONLY #include #include #include #include int main(void) { // this paragraph is entirely optional but related to something we do in RcppSpdlog std::string logname = "my_demo"; // fix a name for this logger auto sp = spdlog::get(logname); // retrieve existing one if (sp == nullptr) sp = spdlog::stderr_color_mt(logname);// or create new one if needed spdlog::set_default_logger(sp); // and set as default // change log pattern (changed from [%H:%M:%S %z] [%n] [%^---%L---%$] ) spdlog::set_pattern("[%H:%M:%S.%f] [%n] [%^%L%$] [thread %t] %v"); // eg ./example SPDLOG_LEVEL=my_demo=warn spdlog::cfg::load_env_levels(); // optional too but very cute in the tic-toc sense spdlog::stopwatch sw; // instantiate a stop watch spdlog::info("Welcome to spdlog!"); spdlog::error("Some error message with arg: {}", 1); spdlog::info("Elapsed time: {}", sw); spdlog::warn("Easy padding in numbers like {:08d}", 12); spdlog::critical("Support for int: {0:d}; hex: {0:x}; oct: {0:o}; bin: {0:b}", 42); spdlog::info("Support for floats {:03.2f}", 1.23456); spdlog::info("Positional args are {1} {0}..", "too", "supported"); spdlog::info("{:<30}", "left aligned"); spdlog::info("Elapsed time: {}", sw); } ```
johnkerl commented 1 month ago

Is this something we should add to CMakeLists.txt too where we default it to OFF? Maybe for debug builds it could be INFO.

@nguyenv do you mind if I take this as a follow-on PR?

eddelbuettel commented 1 month ago

I looked into this and there is a potentially simpler two-line solution because it is indeed covered upstream. This is should do:

modified   libtiledbsoma/src/utils/logger.cc
@@ -37,6 +37,7 @@
 #include <spdlog/fmt/ostr.h>
 #include <spdlog/sinks/basic_file_sink.h>
 #include <spdlog/sinks/stdout_color_sinks.h>
+#include <spdlog/cfg/env.h>

 namespace tiledbsoma {

@@ -72,6 +73,7 @@ Logger::Logger() {
 #endif
     }
     set_level("INFO");
+    spdlog::cfg::load_env_levels();   // eg ./example SPDLOG_LEVEL=my_demo=warn
 }

 Logger::~Logger() {

Demo, from R for ease of use, but note that this tickles use in R (I also looked into changing the R wrapper package, this is working via the same two-line trick but widely shipped) and then libtiledbsoma in the last two lines:

$ SPDLOG_LEVEL="debug" Rscript -e 'library(tiledbsoma); sdf <- SOMADataFrameOpen("/tmp/tiledb/somadf_ts")'
[2024-09-09 17:35:28.930] [default] [Process: 3125929] [debug] [SOMADataFrameOpen] uri /tmp/tiledb/somadf_ts ts (now)
[2024-09-09 17:35:28.969] [default] [Process: 3125929] [debug] [TileDBObject] initialize SOMADataFrame with '/tmp/tiledb/somadf_ts' at (now)
[2024-09-09 17:35:28.969] [default] [Process: 3125929] [debug] [TileDBArray$open] Opening SOMADataFrame '/tmp/tiledb/somadf_ts' in READ mode
[2024-09-09 17:35:28.970] [default] [Process: 3125929] [debug] [tiledb_array] query is READ
[2024-09-09 17:35:28.975] [default] [Process: 3125929] [debug] [TileDBArray$update_metadata_cache] updating metadata cache for SOMADataFrame '/tmp/tiledb/somadf_ts' in READ
[2024-09-09 17:35:28.977] [tiledbsoma] [Process: 3125929] [Thread: 3125929] [debug] [SOMAArray] static method 'ctx' opening array '/tmp/tiledb/somadf_ts'
[2024-09-09 17:35:28.977] [tiledbsoma] [Process: 3125929] [Thread: 3125929] [debug] [SOMAArray] opening array '/tmp/tiledb/somadf_ts'
$ 

Without the env var nothing is shown or seen:

$ Rscript -e 'library(tiledbsoma); sdf <- SOMADataFrameOpen("/tmp/tiledb/somadf_ts")'
$ 
johnkerl commented 1 month ago

@eddelbuettel kerl/libtiledbsoma-env-logging-level -- thank you! :)