From 7a3fe38e1b6552ac5e7c401f19758295bc25518f Mon Sep 17 00:00:00 2001 From: Elen Kalda Date: Thu, 2 Mar 2023 14:47:29 +0000 Subject: [PATCH 1/4] [TVMC] Fix logging in TVMC Three logger related changes in this patch: * Currently we don't set the output stream on the Python logger, so it defaults to sys.stderr, which means we only get some logger output when the command fails. So set the output stream to sys.stdout * Currently we can add -v flag to anywhere in the command line for tvmc compile, but only between tvmc and run/tune for run and tune. Unify the behaviour such that we can add the flag anywhere on the command line. * Set the effective upper bound of -vs to 3 as 4 could result in NOTSET which would not output anything. --- python/tvm/driver/tvmc/autotuner.py | 1 + python/tvm/driver/tvmc/main.py | 7 ++- python/tvm/driver/tvmc/runner.py | 1 + tests/python/driver/tvmc/test_command_line.py | 43 +++++++++++++++++++ 4 files changed, 50 insertions(+), 2 deletions(-) diff --git a/python/tvm/driver/tvmc/autotuner.py b/python/tvm/driver/tvmc/autotuner.py index bed829ef6b29..9f730cbf3205 100644 --- a/python/tvm/driver/tvmc/autotuner.py +++ b/python/tvm/driver/tvmc/autotuner.py @@ -87,6 +87,7 @@ def add_tune_parser(subparsers, _, json_params): required=True, help="output file to store the tuning records for the tuning process", ) + parser.add_argument("-v", "--verbose", action="count", default=0, help="increase verbosity.") parser.add_argument( "--parallel", default=4, diff --git a/python/tvm/driver/tvmc/main.py b/python/tvm/driver/tvmc/main.py index 22a5053aee5a..a324edc1b63d 100644 --- a/python/tvm/driver/tvmc/main.py +++ b/python/tvm/driver/tvmc/main.py @@ -85,9 +85,12 @@ def _main(argv): parser.add_argument("-h", "--help", action="help", help="show this help message and exit.") args = parser.parse_args(argv) - if args.verbose > 4: - args.verbose = 4 + if args.verbose > 3: + args.verbose = 3 + # See the meaning of the logging levels at + # https://docs.python.org/3/library/logging.html#logging-levels + logging.basicConfig(stream=sys.stdout) logging.getLogger("TVMC").setLevel(40 - args.verbose * 10) if args.version: diff --git a/python/tvm/driver/tvmc/runner.py b/python/tvm/driver/tvmc/runner.py index 76173da1939f..6ec033208bd4 100644 --- a/python/tvm/driver/tvmc/runner.py +++ b/python/tvm/driver/tvmc/runner.py @@ -109,6 +109,7 @@ def add_run_parser(subparsers, main_parser, json_params): "Profiling may also have an impact on inference time, " "making it take longer to be generated. (non-micro devices only)", ) + parser.add_argument("-v", "--verbose", action="count", default=0, help="increase verbosity.") parser.add_argument( "--end-to-end", action="store_true", diff --git a/tests/python/driver/tvmc/test_command_line.py b/tests/python/driver/tvmc/test_command_line.py index af45f0bb7e00..c4075321789b 100644 --- a/tests/python/driver/tvmc/test_command_line.py +++ b/tests/python/driver/tvmc/test_command_line.py @@ -18,6 +18,7 @@ import platform import pytest import shutil +import re from pytest_lazyfixture import lazy_fixture from unittest import mock @@ -210,3 +211,45 @@ def test_tvmc_compile_input_model(mock_compile_model, tmpdir_factory, model): _main(run_arg) mock_compile_model.assert_called_once() + + +# TODO(ekalda): This test just makes sure that we log - unfortunately pytest seems to intercept +# the logging output, so we can't test whether it actually writes the logging output to sys.stdout +def test_tvmc_logger(caplog, tmpdir_factory, keras_simple): + tmpdir = tmpdir_factory.mktemp("out") + + # TUNE + log_path = os.path.join(tmpdir, "records.json") + tune_cmd = f"tvmc tune --target llvm -vvvv --output {log_path} " f"--trials 2 {keras_simple}" + + tuning_args = tune_cmd.split(" ")[1:] + _main(tuning_args) + + # Check that we log during tvmc tune + for log_str in ("DEBUG", "INFO", "WARNING", "TVMC"): + assert log_str in caplog.text + + caplog.clear() + + # COMPILE + module_file = os.path.join(tmpdir, "m.tar") + compile_cmd = f"tvmc compile --target 'llvm' {keras_simple} -vvvv --output {module_file}" + + compile_args = compile_cmd.split(" ")[1:] + _main(compile_args) + + # Check that we log during tvmc compile + for log_str in ("DEBUG", "WARNING", "TVMC"): + assert log_str in caplog.text + + caplog.clear() + + # RUN + run_cmd = f"tvmc run -vvvv {module_file}" + + run_args = run_cmd.split(" ")[1:] + _main(run_args) + + # Check that we log during tvmc run + for log_str in ("DEBUG", "TVMC"): + assert log_str in caplog.text From 0b0b6234e453289243695209121bb7b6d0b14c20 Mon Sep 17 00:00:00 2001 From: Elen Kalda Date: Thu, 2 Mar 2023 15:56:37 +0000 Subject: [PATCH 2/4] Remove unused import Change-Id: I49554e5bbac4332f1db8ad0c7fbfce4001dbf36a --- tests/python/driver/tvmc/test_command_line.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/python/driver/tvmc/test_command_line.py b/tests/python/driver/tvmc/test_command_line.py index c4075321789b..00195b758294 100644 --- a/tests/python/driver/tvmc/test_command_line.py +++ b/tests/python/driver/tvmc/test_command_line.py @@ -18,7 +18,6 @@ import platform import pytest import shutil -import re from pytest_lazyfixture import lazy_fixture from unittest import mock From 2d13df59cce0609af45a9156fa64eede2f1e4159 Mon Sep 17 00:00:00 2001 From: Elen Kalda Date: Tue, 14 Mar 2023 15:47:19 +0000 Subject: [PATCH 3/4] Add test to check setting basicConfig --- tests/python/driver/tvmc/test_command_line.py | 22 +++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/tests/python/driver/tvmc/test_command_line.py b/tests/python/driver/tvmc/test_command_line.py index 00195b758294..96e600d2c11f 100644 --- a/tests/python/driver/tvmc/test_command_line.py +++ b/tests/python/driver/tvmc/test_command_line.py @@ -18,6 +18,8 @@ import platform import pytest import shutil +import logging +import sys from pytest_lazyfixture import lazy_fixture from unittest import mock @@ -26,6 +28,7 @@ from tvm.driver.tvmc.main import _main from tvm.driver.tvmc.model import TVMCException from tvm.driver.tvmc import compiler +from unittest.mock import MagicMock @pytest.mark.skipif( @@ -212,8 +215,6 @@ def test_tvmc_compile_input_model(mock_compile_model, tmpdir_factory, model): mock_compile_model.assert_called_once() -# TODO(ekalda): This test just makes sure that we log - unfortunately pytest seems to intercept -# the logging output, so we can't test whether it actually writes the logging output to sys.stdout def test_tvmc_logger(caplog, tmpdir_factory, keras_simple): tmpdir = tmpdir_factory.mktemp("out") @@ -252,3 +253,20 @@ def test_tvmc_logger(caplog, tmpdir_factory, keras_simple): # Check that we log during tvmc run for log_str in ("DEBUG", "TVMC"): assert log_str in caplog.text + + +# Unfortunately pytest seems to intercept the logging output, so we can't test whether it +# actually writes the logging output to sys.stdout, but we can test that we call +# logging.basicConfig with the correct arguments +def test_tvmc_logger_set_basicConfig(monkeypatch, tmpdir_factory, keras_simple): + mock_basicConfig = MagicMock() + monkeypatch.setattr(logging, "basicConfig", mock_basicConfig) + + # Run a random tvmc command + tmpdir = tmpdir_factory.mktemp("out") + module_file = os.path.join(tmpdir, "m.tar") + compile_cmd = f"tvmc compile --target 'llvm' {keras_simple} -vvvv --output {module_file}" + compile_args = compile_cmd.split(" ")[1:] + _main(compile_args) + + mock_basicConfig.assert_called_with(stream=sys.stdout) From bcdc81ee50236414001ec01f970add713428051d Mon Sep 17 00:00:00 2001 From: Elen Kalda Date: Wed, 15 Mar 2023 11:14:24 +0000 Subject: [PATCH 4/4] Add pytest.importorskip("tensorflow") to the tests --- tests/python/driver/tvmc/test_command_line.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/python/driver/tvmc/test_command_line.py b/tests/python/driver/tvmc/test_command_line.py index 96e600d2c11f..6ec1fecd9754 100644 --- a/tests/python/driver/tvmc/test_command_line.py +++ b/tests/python/driver/tvmc/test_command_line.py @@ -216,6 +216,7 @@ def test_tvmc_compile_input_model(mock_compile_model, tmpdir_factory, model): def test_tvmc_logger(caplog, tmpdir_factory, keras_simple): + pytest.importorskip("tensorflow") tmpdir = tmpdir_factory.mktemp("out") # TUNE @@ -259,6 +260,7 @@ def test_tvmc_logger(caplog, tmpdir_factory, keras_simple): # actually writes the logging output to sys.stdout, but we can test that we call # logging.basicConfig with the correct arguments def test_tvmc_logger_set_basicConfig(monkeypatch, tmpdir_factory, keras_simple): + pytest.importorskip("tensorflow") mock_basicConfig = MagicMock() monkeypatch.setattr(logging, "basicConfig", mock_basicConfig)