[KUNLUNXIN][BUF-FIX]fix that transformer engine disable benchmark logger - #1241
Conversation
d27ab85 to
78d17d2
Compare
| try: | ||
| from transformer_engine.pytorch import cpp_extensions as tex | ||
|
|
||
| # note: the transformer_engine has its' own logging which may have conflict with flag_gems logging |
There was a problem hiding this comment.
so ... what do you mean by conflict?
both of them are logging to stdout/stderr?
what's your intention by adding this note here?
There was a problem hiding this comment.
The "conflict" mentioned here refers to a Root Logger configuration conflict , rather than a simple stdout/stderr output issue.
The FlagGems benchmark relies on logging.basicConfig(filename=...) to write performance results to result_*.log . However, logging.basicConfig is designed to be a no-op (ignored) if the Root Logger already has handlers configured.
We observed that in certain versions of transformer_engine (specifically on Python 3.10 in our environment), importing the module registers a StreamHandler to the Root Logger during initialization. This causes our subsequent basicConfig call to be ignored, resulting in missing result files.
This behavior can be verified with the following one-liner:
python -c "import logging; print('before', logging.root.handlers); import transformer_engine.pytorch.cpp_extensions as tex; print('after', logging.root.handlers)"
Output (Python 3.10):
before []
after [<StreamHandler <stderr> (NOTSET)>]
As shown, the Root Logger acquires a StreamHandler after the import. This issue has also been discussed in NVIDIA/TransformerEngine#1065 .
Fix: To resolve this robustly, we have switched to using a dedicated RecordLogger with an explicit FileHandler for writing benchmark results, which operates independently of the Root Logger's state.
There was a problem hiding this comment.
Great. Thanks for the elaborated feedback. We'll track this issue.
78d17d2 to
2b046fa
Compare
| pass | ||
|
|
||
| handler = logging.FileHandler(log_file, mode="w", encoding="utf-8") | ||
| handler.setLevel(logging.INFO) |
There was a problem hiding this comment.
wait a min, the default logger in global level is debug, should we keep the same log level?
There was a problem hiding this comment.
This logger is dedicated to recording benchmark results (metrics & JSON summaries) rather than debug traces.
Using logging.INFO is intentional here because we only want to capture the final performance data. Setting it to DEBUG isn't necessary for this purpose and might introduce unwanted noise if we ever add debug logs to this specific logger in the future.
We are strictly maintaining the original behavior, as the previous code also used level=logging.INFO.

| handler.setLevel(logging.INFO) | ||
| handler.setFormatter(logging.Formatter("[%(levelname)s] %(message)s")) | ||
| recordLogger.addHandler(handler) | ||
| recordLogger.setLevel(logging.INFO) |
There was a problem hiding this comment.
may I know why setLevel twice?
There was a problem hiding this comment.
This is necessary because we are configuring a named non-root logger to isolate our benchmark results, which follows the standard Python logging behavior (as seen in the Logging Cookbook ).
Why set level twice?
-
recordLogger.setLevel(logging.INFO) :
Purpose : Overrides the default level inheritance.
Reason : By default, a named logger inherits the Root Logger's level (usually WARNING ). If we don't explicitly set this logger to INFO , our messages will be filtered out before they even reach any handlers. -
handler.setLevel(logging.INFO) :
Purpose : Ensures this specific FileHandler records INFO messages.
Reason : While strictly setting the Logger level is often sufficient if the Handler is NOTSET , explicitly setting the Handler level is a best practice recommended by the Python docs to guarantee that this specific sink receives the intended logs, regardless of future changes to the logger hierarchy.
So, setting both ensures our log isolation works correctly and robustly."
| ) | ||
| print(attri) | ||
| logging.info(attri.to_dict()) | ||
| recordLogger.info(attri.to_dict()) |
There was a problem hiding this comment.
Sorry, I don't get time to go through all 374 lines above.
@kiddyjinjin , do we tested logger = logging.getLogger("flag_gems.benchmark.record") before?
My question: as default logger(logging.getLogger) is able to log file by enable_gems(....), and in this file, which using logging without getLogger seems wrong.
Back to Since this PR focuses on fixing the missing log file issue.... Which means, we confirmed and tested the log file will missing in benchmark testing, when both enable_gems(....) and logging.getLogger configured by design?
There was a problem hiding this comment.
Let me clarify the relationship between enable_gems and this fix, and provide evidence for the issue.
- Relationship with enable_gems(...) : They are independent.
- enable_gems(...) configures the runtime debug logger (e.g., logging.getLogger("flag_gems") ) for operator dispatch info.
- This PR addresses the benchmark result logger (previously using Root Logger, now flag_gems.benchmark.record ), which stores the final performance metrics (JSON).
Using logging.getLogger in this PR is the correct practice to isolate these two purposes and avoid conflicts.
-
The Verified Issue: We confirmed that transformer_engine (verified on version 1.13.0+7a6085c with Python 3.10) automatically configures the Root Logger during import. This causes the subsequent logging.basicConfig in our benchmark suite to be ignored (no-op), resulting in missing log files .
-
Verification Steps: You can verify this conflict with this one-liner:
python -c "import logging; print('Before:', logging.root.handlers); import transformer_engine.
pytorch.cpp_extensions as tex; print('After:', logging.root.handlers)"
Output:
Before: []
After: [<StreamHandler <stderr> (NOTSET)>] <-- This handler blocks our basicConfig
Conclusion: We have tested that without this fix, pytest ... --record log fails to generate the result file in this environment. This PR fixes it by using a dedicated logger that bypasses the polluted Root Logger.
There was a problem hiding this comment.
@tengqm , I will skip review this PR for now.
FlagGems/benchmark/performance_utils.py
Lines 427 to 428 in 4eda19f
I am confusing....it seems we are not using standard pytest or pytest-benchmark plugin....
and this PR just to save metrics result....
seems we have print and logging... so... just pytest xxx > some_file and change result.to_json() from logging.info to print will work?
@kiddyjinjin , @dongjibin1996 please move/go ahead.
4fcb756
2b046fa to
4fcb756
Compare
|
@dongjibin1996 Thank you for your patience in letting the team know the dilemma we have at hand. The challenges we put forward were an attempt to better understand the status quo. They are not meant to be sorts of blocker. Only when we really understand the pain points can we come up with some ideas to help get things better. |
the transformer_engine may disable flagGems benchMark logging, which lead to "pytest --record log" failure
4fcb756 to
1e25765
Compare
…m-engine-disable-benchmark-logger
…ger (flagos-ai#1241) the transformer_engine may disable flagGems benchMark logging, which lead to "pytest --record log" failure
the transformer_engine may disable flagGems benchMark logging, which lead to "pytest --record log" failure
PR Category
OP Test
Type of Change
Bug Fix
Progress
repair issue #1242