Kyösti Mälkki has uploaded this change for review. ( https://review.coreboot.org/c/coreboot/+/37425 )
Change subject: device: Log times with millisecond resolution ......................................................................
device: Log times with millisecond resolution
To print times with 1 us resolution just adds unnecessary noise when comparing logs across different boots. Furthermore, just the printk itself is 1 ms if some slow console is enabled.
If bus scan or device init takes less than 2 ms it's not really worth printing the time at all.
Change-Id: Ibea43124a1937f404a6e71fd9431086b2b72290a Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/device/device.c 1 file changed, 21 insertions(+), 12 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/25/37425/1
diff --git a/src/device/device.c b/src/device/device.c index 5d9938f..511e09b 100644 --- a/src/device/device.c +++ b/src/device/device.c @@ -903,8 +903,7 @@ { int do_scan_bus; struct stopwatch sw; - - stopwatch_init(&sw); + long scan_time;
if (!busdev->enabled) return; @@ -913,6 +912,8 @@
post_log_path(busdev);
+ stopwatch_init(&sw); + do_scan_bus = 1; while (do_scan_bus) { struct bus *link; @@ -928,8 +929,13 @@ } }
- printk(BIOS_DEBUG, "%s: scanning of bus %s took %ld usecs\n", - __func__, dev_path(busdev), stopwatch_duration_usecs(&sw)); + scan_time = stopwatch_duration_msecs(&sw); + if (scan_time >= 2) { + printk(BIOS_DEBUG, "%s: bus %s finished in %ld msecs\n", __func__, + dev_path(busdev), scan_time); + } else { + printk(BIOS_DEBUG, "%s: bus %s done\n", __func__, dev_path(busdev)); + } }
void scan_bridges(struct bus *bus) @@ -1116,22 +1122,25 @@ return;
if (!dev->initialized && dev->ops && dev->ops->init) { -#if CONFIG(HAVE_MONOTONIC_TIMER) struct stopwatch sw; - stopwatch_init(&sw); -#endif + long init_time; + if (dev->path.type == DEVICE_PATH_I2C) { printk(BIOS_DEBUG, "smbus: %s[%d]->", dev_path(dev->bus->dev), dev->bus->link_num); }
- printk(BIOS_DEBUG, "%s init ...\n", dev_path(dev)); + printk(BIOS_DEBUG, "%s init\n", dev_path(dev)); + + stopwatch_init(&sw); dev->initialized = 1; dev->ops->init(dev); -#if CONFIG(HAVE_MONOTONIC_TIMER) - printk(BIOS_DEBUG, "%s init finished in %ld usecs\n", dev_path(dev), - stopwatch_duration_usecs(&sw)); -#endif + + init_time = stopwatch_duration_msecs(&sw); + if (init_time >= 2) { + printk(BIOS_DEBUG, "%s init finished in %ld msecs\n", dev_path(dev), + init_time); + } } }
Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37425 )
Change subject: device: Log times with millisecond resolution ......................................................................
Patch Set 3: Code-Review+1
(1 comment)
https://review.coreboot.org/c/coreboot/+/37425/3//COMMIT_MSG Commit Message:
https://review.coreboot.org/c/coreboot/+/37425/3//COMMIT_MSG@14 PS3, Line 14: worth printing the time at all. Hmmm, I think I would prefer to print it for consistency. It might confuse people to see the same message sometimes with and sometimes without numbers.
Hello build bot (Jenkins), Nico Huber,
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/37425
to look at the new patch set (#4).
Change subject: device: Log times with millisecond resolution ......................................................................
device: Log times with millisecond resolution
To print times with 1 us resolution just adds unnecessary noise when comparing logs across different boots. Furthermore, just the printk itself is 1 ms if some slow console is enabled.
Change-Id: Ibea43124a1937f404a6e71fd9431086b2b72290a Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/device/device.c 1 file changed, 15 insertions(+), 12 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/25/37425/4
Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37425 )
Change subject: device: Log times with millisecond resolution ......................................................................
Patch Set 4: Code-Review+2
(2 comments)
https://review.coreboot.org/c/coreboot/+/37425/3//COMMIT_MSG Commit Message:
https://review.coreboot.org/c/coreboot/+/37425/3//COMMIT_MSG@14 PS3, Line 14: worth printing the time at all.
Hmmm, I think I would prefer to print it for consistency. It might […]
Done
https://review.coreboot.org/c/coreboot/+/37425/4/src/device/device.c File src/device/device.c:
https://review.coreboot.org/c/coreboot/+/37425/4/src/device/device.c@911 PS4, Line 911: BIOS_SPEW While we are at it, should we make this BIOS_DEBUG? That would also match better with the removed "scanning" in the string below.
Hello build bot (Jenkins), Nico Huber,
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/37425
to look at the new patch set (#5).
Change subject: device: Log times with millisecond resolution ......................................................................
device: Log times with millisecond resolution
To print times with 1 us resolution just adds unnecessary noise when comparing logs across different boots. Furthermore, just the printk itself is 1 ms if some slow console is enabled.
Change-Id: Ibea43124a1937f404a6e71fd9431086b2b72290a Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/device/device.c 1 file changed, 16 insertions(+), 13 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/25/37425/5
Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37425 )
Change subject: device: Log times with millisecond resolution ......................................................................
Patch Set 5:
(1 comment)
https://review.coreboot.org/c/coreboot/+/37425/4/src/device/device.c File src/device/device.c:
https://review.coreboot.org/c/coreboot/+/37425/4/src/device/device.c@911 PS4, Line 911: BIOS_SPEW
While we are at it, should we make this BIOS_DEBUG? That would […]
Done
Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37425 )
Change subject: device: Log times with millisecond resolution ......................................................................
Patch Set 5: Code-Review+2
Nico Huber has submitted this change. ( https://review.coreboot.org/c/coreboot/+/37425 )
Change subject: device: Log times with millisecond resolution ......................................................................
device: Log times with millisecond resolution
To print times with 1 us resolution just adds unnecessary noise when comparing logs across different boots. Furthermore, just the printk itself is 1 ms if some slow console is enabled.
Change-Id: Ibea43124a1937f404a6e71fd9431086b2b72290a Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com Reviewed-on: https://review.coreboot.org/c/coreboot/+/37425 Tested-by: build bot (Jenkins) no-reply@coreboot.org Reviewed-by: Nico Huber nico.h@gmx.de --- M src/device/device.c 1 file changed, 16 insertions(+), 13 deletions(-)
Approvals: build bot (Jenkins): Verified Nico Huber: Looks good to me, approved
diff --git a/src/device/device.c b/src/device/device.c index 5d9938f..236b768 100644 --- a/src/device/device.c +++ b/src/device/device.c @@ -903,16 +903,17 @@ { int do_scan_bus; struct stopwatch sw; - - stopwatch_init(&sw); + long scan_time;
if (!busdev->enabled) return;
- printk(BIOS_SPEW, "%s scanning...\n", dev_path(busdev)); + printk(BIOS_DEBUG, "%s scanning...\n", dev_path(busdev));
post_log_path(busdev);
+ stopwatch_init(&sw); + do_scan_bus = 1; while (do_scan_bus) { struct bus *link; @@ -928,8 +929,9 @@ } }
- printk(BIOS_DEBUG, "%s: scanning of bus %s took %ld usecs\n", - __func__, dev_path(busdev), stopwatch_duration_usecs(&sw)); + scan_time = stopwatch_duration_msecs(&sw); + printk(BIOS_DEBUG, "%s: bus %s finished in %ld msecs\n", __func__, + dev_path(busdev), scan_time); }
void scan_bridges(struct bus *bus) @@ -1116,22 +1118,23 @@ return;
if (!dev->initialized && dev->ops && dev->ops->init) { -#if CONFIG(HAVE_MONOTONIC_TIMER) struct stopwatch sw; - stopwatch_init(&sw); -#endif + long init_time; + if (dev->path.type == DEVICE_PATH_I2C) { printk(BIOS_DEBUG, "smbus: %s[%d]->", dev_path(dev->bus->dev), dev->bus->link_num); }
- printk(BIOS_DEBUG, "%s init ...\n", dev_path(dev)); + printk(BIOS_DEBUG, "%s init\n", dev_path(dev)); + + stopwatch_init(&sw); dev->initialized = 1; dev->ops->init(dev); -#if CONFIG(HAVE_MONOTONIC_TIMER) - printk(BIOS_DEBUG, "%s init finished in %ld usecs\n", dev_path(dev), - stopwatch_duration_usecs(&sw)); -#endif + + init_time = stopwatch_duration_msecs(&sw); + printk(BIOS_DEBUG, "%s init finished in %ld msecs\n", dev_path(dev), + init_time); } }
-
Kyösti Mälkki (Code Review) -
Nico Huber (Code Review)