[BugFix] respect VLLM_LOGGING_LEVEL in logger

[BoyuanFeng]

Issue: vLLM defaults logger vllm to be DEBUG (Line 65). envs.VLLM_LOGGING_LEVEL is used to update DEFAULT_LOGGING_CONFIG["handlers"]["vllm"] (aka logging.StreamHandler), but not DEFAULT_LOGGING_CONFIG["loggers"]["vllm"] (aka logging.vllm). logging.vllm is DEBUG and used as the parent of all other loggers, including execute_model.

vllm/vllm/logger.py

Lines 40 to 71 in 1336a1e

	DEFAULT_LOGGING_CONFIG = {
	"formatters": {
	"vllm": {
	"class": "vllm.logging_utils.NewLineFormatter",
	"datefmt": _DATE_FORMAT,
	"format": _FORMAT,
	},
	"vllm_color": {
	"class": "vllm.logging_utils.ColoredFormatter",
	"datefmt": _DATE_FORMAT,
	"format": _FORMAT,
	},
	},
	"handlers": {
	"vllm": {
	"class": "logging.StreamHandler",
	# Choose formatter based on color setting.
	"formatter": "vllm_color" if _use_color() else "vllm",
	"level": envs.VLLM_LOGGING_LEVEL,
	"stream": envs.VLLM_LOGGING_STREAM,
	},
	},
	"loggers": {
	"vllm": {
	"handlers": ["vllm"],
	"level": "DEBUG",
	"propagate": False,
	},
	},
	"version": 1,
	"disable_existing_loggers": False,
	}

This PR fixed the issue.

[chatgpt-codex-connector]

Codex usage limits have been reached for code reviews. Please check with the admins of this repo to increase the limits by adding credits.

[gemini-code-assist]

Code Review

This pull request removes a debug logging statement from the execute_model function to reduce latency on a performance-critical path. While this change achieves its performance goal, I have raised a high-severity concern regarding maintainability. The removed log provides valuable information for debugging complex features like CUDA graphs and distributed execution. I've suggested an alternative approach to conditionally enable this log via an environment variable, which would preserve debuggability for developers without impacting production performance.

[ProExpertProg]

What if we save a bool property on the object that controls this log and use an if statement on the hot path, perhaps that's better?

[BoyuanFeng]

yes added an observability_config to control that.

[ProExpertProg]

I was actually referring to using if logger.isEnabledFor(logging.DEBUG):, but I see that you're having issues with that

[BoyuanFeng]

logger.isEnabledFor still adds ~1 us latency so I kept the observability config

[njhill]

@BoyuanFeng is the concern overhead when debug level logging is enabled, or even when it's disabled (default case)? The latter would be quite surprising, the function call should really be a no-op.

[BoyuanFeng]

@njhill when running vllm bench latency, gpu_model_runner.py gives

logger.isEnabledFor(logging.DEBUG): True
logging.getLevelName(logger.level): NOTSET
logging.getLevelName(logger.getEffectiveLevel()): DEBUG

So the logger.debug is not a no-op. We can also observe it in the profile trace if we run VLLM_TORCH_PROFILER_DIR="../vllm_profile" vllm bench latency --profile.

[njhill]

@BoyuanFeng I'm still confused why debug logging is enabled. It's probably best for that to be disabled when benchmarking. Are you sure you aren't separately setting the env var export VLLM_LOGGING_LEVEL=DEBUG?

[ProExpertProg]

I agree with @njhill, I am confused why the logging level is debug by default, it isn't for me

[BoyuanFeng]

@njhill @ProExpertProg I found that vLLM defaults logger vllm to be DEBUG (Line 65). envs.VLLM_LOGGING_LEVEL is used to update DEFAULT_LOGGING_CONFIG["handlers"]["vllm"] (aka logging.StreamHandler), but not DEFAULT_LOGGING_CONFIG["loggers"]["vllm"] (aka logging.vllm). logging.vllm is DEBUG and used as the parent of all other loggers, including execute_model.

vllm/vllm/logger.py

Lines 40 to 71 in 1336a1e

	DEFAULT_LOGGING_CONFIG = {
	"formatters": {
	"vllm": {
	"class": "vllm.logging_utils.NewLineFormatter",
	"datefmt": _DATE_FORMAT,
	"format": _FORMAT,
	},
	"vllm_color": {
	"class": "vllm.logging_utils.ColoredFormatter",
	"datefmt": _DATE_FORMAT,
	"format": _FORMAT,
	},
	},
	"handlers": {
	"vllm": {
	"class": "logging.StreamHandler",
	# Choose formatter based on color setting.
	"formatter": "vllm_color" if _use_color() else "vllm",
	"level": envs.VLLM_LOGGING_LEVEL,
	"stream": envs.VLLM_LOGGING_STREAM,
	},
	},
	"loggers": {
	"vllm": {
	"handlers": ["vllm"],
	"level": "DEBUG",
	"propagate": False,
	},
	},
	"version": 1,
	"disable_existing_loggers": False,
	}

[ProExpertProg]

Huh this seems like a big issue - we should update this as there are other places in the code we assume that debug logs are noops (and clearly they aren't). Can you open a new PR where we just update the logger level?

[njhill]

Wow, nice find! Looks like it has been this way all along and we've been paying more for debug logs than we should have been (even though the output is blocked by the handler, some processing is still done for each log record).

It should be a trivial fix hopefully, let's get it into the upcoming release.

[njhill]

Please revert all the changes apart from those in logger.py. Then this looks good! (or open a separate PR for that as @ProExpertProg suggested)

[BoyuanFeng]

@njhill cleaned this pr to only contain changes in logger.py. I will open another pr for logger.debug overhead

[njhill]

Thanks @BoyuanFeng! I'm hoping this change should be sufficient.

[njhill]

@BoyuanFeng it looks like there's some tests which rely on capturing debug logs and so also need to be updated.

[njhill]

We can probably get around this quickly by adding VLLM_LOGGING_LEVEL=DEBUG to the tests in question in test-pipeline.yaml (looks like there's only two so far, can wait for the current CI run to finish first to make sure there aren't any more).

[BoyuanFeng]

@njhill yeah fixed the tests. let's see if something is missed.