Skip to content

Commit f78d256

Browse files
avmanerikaravmanerikar
committed
rfcs: add proposal for verbose logging support
1 parent b316f50 commit f78d256

File tree

1 file changed

+114
-0
lines changed
  • rfcs/20240311-verbose-logging-support

1 file changed

+114
-0
lines changed

‎rfcs/20240311-verbose-logging-support/README.md

+114
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,114 @@
1+
# Proposal for a Logging Mechanism in oneDNN
2+
3+
## Motivation
4+
5+
This is a proposal to introduce a logging mechanism within the oneDNN framework to direct, save and manage the verbose outputs generated from oneDNN into user-specified logs.
6+
Presently, oneDNN in the verbose mode prints all information directly to the console using `stdout` - with a logging mechanism, the user will be able to create custom logs by controlling what and how verbose information is saved in the user-specified logfiles.
7+
8+
## Objectives
9+
The logging mechanism will be introduced in oneDNN with the following features:
10+
- deploy logging support as an experimental feature enabled by setting EXPERIMENTAL_LOGGER=ON.
11+
- add runtime control variables to specify logging options like logfile path and logging levels.
12+
- implement formatting specifications for verbose outputs printed to the log files.
13+
14+
## Proposal
15+
The proposal is to implement logging support in oneDNN with the help of [`spdlog`]((https://github.com/gabime/spdlog)), a header-only C++ logging library which provides a Python-like formatting API using the bundled [fmt](https://github.com/fmtlib/fmt) lib. The library uses an MIT license, has no cross-component dependencies and has a distinct performance [gain](https://github.com/gabime/spdlog/tree/v1.x?tab=readme-ov-file#benchmarks) over `sprintf` for logging. Key considerations for the proposal are listed as follows:
16+
17+
### 1. Build-time Variables - ONEDNN_EXPERIMENTAL_LOGGING
18+
`spdlog` can be built with oneDNN using a header-only approach by adding the library headers to the build tree. A pre-compiled version is recommended by the authors to reduce compilation overhead but is not required since the implementation will utilize only limited features from the entire scope of `spdlog`.
19+
20+
Logging options in oneDNN will be enabled as an experimental feature by setting the variable `ONEDNN_EXPERIMENTAL_LOGGING=ON` during build-time. This will also take an header-based apporach by building the fmtlib library and spdlog headers into the code to enable the logger mechanism.
21+
22+
### 2. Runtime Logging Controls - ONEDNN_VERBOSE_LOGFILE, ONEDNN_VERBOSE_LOGFILE_SIZE, ONEDNN_VERBOSE_NUM_LOGFILES
23+
A basic requirement for implementing logging support will be to define the run-time variables which the user can specify to manage oneDNN data logging:
24+
- For the simple case where the logging mechanism involves directly dumping the verbose outputs into a logfile, this can be accomplished with one control variable for specifying the logfile path (`ONEDNN_VERBOSE_LOGFILE=/path/to/file`).
25+
Specifying `ONEDNN_VERBOSE_LOGFILE` automatically enables logging of the verbose output to the user-specified file while in the default case, the data is directly printed to `stdout`.
26+
In this scenario, the data recorded in the logfile mirrors the printed verbose mode information, hence, the logged data can be managed using oneDNN [runtime controls](https://oneapi-src.github.io/oneDNN/dev_guide_verbose.html?highlight=onednn_verbose#run-time-controls) for the verbose mode.
27+
- By default, data will be recorded using a rotating lazy logger with a file size specified by `ONEDNN_VERBOSE_LOGFILE_SIZE(=1024*1024*50)` and the number of rotating files specified by `ONEDNN_VERBOSE_NUM_LOGFILES(=5)`.
28+
- An additional runtime variable `ONEDNN_VERBOSE_LOG_WITH_CONSOLE` will also the user to print to both the logfiles and to `stdout`.
29+
30+
### 3. Alignment and Specification of Logging Levels
31+
`spdlog` defines the following levels for data logging in its implementation:
32+
```
33+
#define SPDLOG_LEVEL_TRACE 0
34+
#define SPDLOG_LEVEL_DEBUG 1
35+
#define SPDLOG_LEVEL_INFO 2
36+
#define SPDLOG_LEVEL_WARN 3
37+
#define SPDLOG_LEVEL_ERROR 4
38+
#define SPDLOG_LEVEL_CRITICAL 5
39+
#define SPDLOG_LEVEL_OFF 6
40+
```
41+
42+
The type of tracing information logged for each of these levels is evident from their names. Comparing with the different [verbose modes](https://oneapi-src.github.io/oneDNN/dev_guide_verbose.html?highlight=onednn_verbose#run-time-controls) defined for oneDNN, these logging levels can be aligned with the verbose modes as follows:
43+
44+
| | `spdlog` Level | oneDNN Verbose Mode |
45+
|---|-----------------------|------------------------------------------------------------------|
46+
| 0 | SPDLOG_LEVEL_TRACE | `all` |
47+
| 1 | SPDLOG_LEVEL_DEBUG | `debuginfo=<level>` |
48+
| 2 | SPDLOG_LEVEL_INFO | `dispatch`, `profile_create`, `profile_exec`, `profile` |
49+
| 3 | SPDLOG_LEVEL_WARNING | --- |
50+
| 4 | SPDLOG_LEVEL_ERROR | `check` |
51+
| 5 | SPDLOG_LEVEL_CRITICAL | `error` |
52+
| 6 | SPDLOG_LEVEL_OFF | `none` |
53+
54+
With this alignment, the tracing information printed out for each verbose mode can be also logged at the aligned level. Obviously, the logging level here is determined from the value of the `ONEDNN_VERBOSE` variable.
55+
56+
### 4. Formatting Specifications for Logging
57+
The printed verbose information when `ONEDNN_VERBOSE=all` is formatted and contains the following fields as described [here](https://oneapi-src.github.io/oneDNN/dev_guide_verbose.html#decrypting-the-output):
58+
```
59+
onednn_verbose,primitive,info,template:timestamp,operation,engine,primitive,implementation,prop_kind,memory_descriptors,attributes,auxiliary,problem_desc,exec_time
60+
onednn_verbose,graph,info,template:timestamp,operation,engine,partition_id,partition_kind,op_names,data_formats,logical_tensors,fpmath_mode,backend,exec_time
61+
onednn_verbose,1693533460193.346924,primitive,create:cache_miss,cpu,convolution,jit:avx512_core,forward_training,src_f32:a:blocked:aBcd16b::f0 wei_f32:a:blocked:ABcd16b16a::f0 bia_f32:a:blocked:a::f0 dst_f32:a:blocked:aBcd16b::f0,,alg:convolution_direct,mb2_ic16oc16_ih7oh7kh5sh1dh0ph2_iw7ow7kw5sw1dw0pw2,0.709961
62+
```
63+
64+
When logging is enabled, the data will be recorded in the logfiles with the same format and field with the following spdlog field prepended to the verbose output:
65+
66+
```
67+
[%Y-%M-%D %H:%M:%S][onednn][log_level] verbose field 0,verbose field 1, ...
68+
```
69+
70+
#### Example Log:
71+
```
72+
[2024-07-08 17:41:40.417] [oneDNN] [info] -------------------------------------------------
73+
[2024-07-08 17:41:40.417] [oneDNN] [info] logger enabled,logfile:./logs/test_logger.log,size::52428800,amt::5
74+
[2024-07-08 17:41:40.417] [oneDNN] [info] -------------------------------------------------
75+
...
76+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,info,cpu,runtime:OpenMP,nthr:224
77+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,info,cpu,isa:Intel AVX-512 with float16, Intel DL Boost and bfloat16 support
78+
...
79+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,info,experimental features are enabled
80+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,primitive,info,template:
81+
[2024-07-08 17:41:40.427] [oneDNN] [info] operation,engine,primitive,implementation,prop_kind,memory_descriptors,attributes,auxiliary,problem_desc,exec_time
82+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,info,experimental functionality for logging is enabled
83+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,graph,info,template:
84+
[2024-07-08 17:41:40.427] [oneDNN] [info] operation,engine,partition_id,partition_kind,op_names,data_formats,logical_tensors,fpmath_mode,backend,exec_time
85+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,primitive,create:dispatch,matmul,cpu,matmul,brg_matmul:avx10_1_512_amx_fp16,undef,src_f32::blocked:abc::f0 wei_f32::blocked:abc::f0 bia_f32::blocked:abc::f0_mask4 dst_f32::blocked:abc::f0,attr-post-ops:eltwise_relu,,3x128x256:3x256x512,unsupported isa,src/cpu/x64/matmul/brgemm_matmul.cpp:101
86+
[2024-07-08 17:41:40.427] [oneDNN] [info] onednn_verbose,primitive,create:dispatch,matmul,cpu,matmul,brg_matmul:avx10_1_512_amx,undef,src_f32::blocked:abc::f0 wei_f32::blocked:abc::f0 bia_f32::blocked:abc::f0_mask4 dst_f32::blocked:abc::f0,attr-post-ops:eltwise_relu,,3x128x256:3x256x512,unsupported isa,src/cpu/x64/matmul/brgemm_matmul.cpp:101
87+
...
88+
```
89+
90+
## Usage
91+
- For normal verbose mode without logging:
92+
```
93+
$ ONEDNN_VERBOSE=all ./examples/primitives-matmul-cpp
94+
```
95+
- For verbose mode with logging:
96+
```
97+
$ ONEDNN_VERBOSE=all ONEDNN_VERBOSE_LOGFILE=~/test_logger.log ./examples/primitives-matmul-cpp
98+
```
99+
- For verbose mode with logging and printing to `stdout`:
100+
```
101+
$ ONEDNN_VERBOSE=all ONEDNN_VERBOSE_LOGFILE=~/test_logger.log ONEDNN_VERBOSE_LOG_WITH_CONSOLE=1 ./examples/primitives-matmul-cpp
102+
```
103+
- With additional controls for logging:
104+
```
105+
$ ONEDNN_VERBOSE=all ONEDNN_VERBOSE_LOGFILE=~/test_logger.log ONEDNN_VERBOSE_LOGFILE_SIZE=102400 ONEDNN_VERBOSE_NUM_LOGFILES=5 ./examples/primitives-matmul-cpp
106+
```
107+
108+
## References
109+
110+
- **spdlog**: https://github.com/gabime/spdlog
111+
- **fmt** lib: https://github.com/fmtlib/fmt
112+
113+
#
114+
(EOD)

0 commit comments

Comments
 (0)