[PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Stefan Kerkmann]

These two patches are the outcome of an investigation why loading a
fitimage from an eMMC took nearly 7s - the sheer amount of generated
debugging messages slowed down the system by a factor of ~21 with
KConfig options:

	CONFIG_COMPILE_LOGLEVEL=7
	CONFIG_DEFAULT_LOGLEVEL=6

Which is the current default combination for barebox.

Before:

	Booting entry 'system0'
	FIT: Reading time: 6722 ms

After:

	Booting entry 'system0'
	FIT: Reading time: 324 ms

Signed-off-by: Stefan Kerkmann <s.kerkmann@pengutronix.de>
---
Stefan Kerkmann (2):
      block: downgrade noisy debug calls to verbose debug
      fs: ramfs: downgrade noisy debug calls to verbose debug

 common/block.c |  4 ++--
 fs/ramfs.c     | 10 +++++-----
 2 files changed, 7 insertions(+), 7 deletions(-)
---
base-commit: 59658c877bcc605fe3ca36653b4f40f57856b81a
change-id: 20241028-fix-noisy-debug-calls-a6d6185be705

Best regards,
-- 
Stefan Kerkmann <s.kerkmann@pengutronix.de>

[PATCH 1/2] block: downgrade noisy debug calls to verbose debug

[Stefan Kerkmann]

These debug calls are in the hotpath of any block device interaction,
cluttering the log buffer, slowing down reads/writes and are usually not
interesting while debugging, thus they are downgraded to verbose
debugging.

Signed-off-by: Stefan Kerkmann <s.kerkmann@pengutronix.de>
---
 common/block.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/common/block.c b/common/block.c
index 3101fceea7..3ee33f2bf0 100644
--- a/common/block.c
+++ b/common/block.c
@@ -105,7 +105,7 @@ static struct chunk *chunk_get_cached(struct block_device *blk, sector_t block)
 	list_for_each_entry(chunk, &blk->buffered_blocks, list) {
 		if (block >= chunk->block_start &&
 				block < chunk->block_start + blk->rdbufsize) {
-			dev_dbg(blk->dev, "%s: found %llu in %d\n", __func__,
+			dev_vdbg(blk->dev, "%s: found %llu in %d\n", __func__,
 				block, chunk->num);
 			/*
 			 * move most recently used entry to the head of the list
@@ -175,7 +175,7 @@ static int block_cache(struct block_device *blk, sector_t block)
 
 	chunk->block_start = block & ~blk->blkmask;
 
-	dev_dbg(blk->dev, "%s: %llu to %d\n", __func__, chunk->block_start,
+	dev_vdbg(blk->dev, "%s: %llu to %d\n", __func__, chunk->block_start,
 		chunk->num);
 
 	len = writebuffer_io_len(blk, chunk);

-- 
2.39.5

[PATCH 2/2] fs: ramfs: downgrade noisy debug calls to verbose debug

[Stefan Kerkmann]

These debug calls are in the hotpath of any ramfs interaction,
cluttering the log buffer, slowing down reads/writes and are usually not
interesting while debugging, thus they are downgraded to verbose
debugging.

Signed-off-by: Stefan Kerkmann <s.kerkmann@pengutronix.de>
---
 fs/ramfs.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/fs/ramfs.c b/fs/ramfs.c
index a799b23efb..c1ef7acd91 100644
--- a/fs/ramfs.c
+++ b/fs/ramfs.c
@@ -224,14 +224,14 @@ static int ramfs_read(struct device *_dev, FILE *f, void *buf, size_t insize)
 	unsigned long pos = f->pos;
 	int size = insize;
 
-	debug("%s: %p %zu @ %lld\n", __func__, node, insize, f->pos);
+	pr_vdebug("%s: %p %zu @ %lld\n", __func__, node, insize, f->pos);
 
 	while (size) {
 		data = ramfs_find_chunk(node, pos, &ofs, &len);
 		if (!data)
 			return -EINVAL;
 
-		debug("%s: pos: %lu ofs: %d len: %d\n", __func__, pos, ofs, len);
+		pr_vdebug("%s: pos: %lu ofs: %d len: %d\n", __func__, pos, ofs, len);
 
 		now = min(size, len);
 
@@ -255,14 +255,14 @@ static int ramfs_write(struct device *_dev, FILE *f, const void *buf,
 	unsigned long pos = f->pos;
 	int size = insize;
 
-	debug("%s: %p %zu @ %lld\n", __func__, node, insize, f->pos);
+	pr_vdebug("%s: %p %zu @ %lld\n", __func__, node, insize, f->pos);
 
 	while (size) {
 		data = ramfs_find_chunk(node, pos, &ofs, &len);
 		if (!data)
 			return -EINVAL;
 
-		debug("%s: pos: %lu ofs: %d len: %d\n", __func__, pos, ofs, len);
+		pr_vdebug("%s: pos: %lu ofs: %d len: %d\n", __func__, pos, ofs, len);
 
 		now = min(size, len);
 
@@ -363,7 +363,7 @@ static int ramfs_truncate(struct device *dev, FILE *f, loff_t size)
 	if (size > ULONG_MAX)
 		return -ENOSPC;
 
-	debug("%s: %p cur: %ld new: %lld alloc: %ld\n", __func__, node,
+	pr_vdebug("%s: %p cur: %ld new: %lld alloc: %ld\n", __func__, node,
 	       node->size, size, node->alloc_size);
 
 	if (size == node->size)

-- 
2.39.5

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Ahmad Fatoum]

Hi,

On 28.10.24 17:17, Stefan Kerkmann wrote:
> These two patches are the outcome of an investigation why loading a
> fitimage from an eMMC took nearly 7s - the sheer amount of generated
> debugging messages slowed down the system by a factor of ~21 with
> KConfig options:
> 
> 	CONFIG_COMPILE_LOGLEVEL=7
> 	CONFIG_DEFAULT_LOGLEVEL=6
> 
> Which is the current default combination for barebox.
> 
> Before:
> 
> 	Booting entry 'system0'
> 	FIT: Reading time: 6722 ms
> 
> After:
> 
> 	Booting entry 'system0'
> 	FIT: Reading time: 324 ms

This is the time with these two patches applied or with
compile log level changed?

Cheers,
Ahmad

> 
> Signed-off-by: Stefan Kerkmann <s.kerkmann@pengutronix.de>
> ---
> Stefan Kerkmann (2):
>       block: downgrade noisy debug calls to verbose debug
>       fs: ramfs: downgrade noisy debug calls to verbose debug
> 
>  common/block.c |  4 ++--
>  fs/ramfs.c     | 10 +++++-----
>  2 files changed, 7 insertions(+), 7 deletions(-)
> ---
> base-commit: 59658c877bcc605fe3ca36653b4f40f57856b81a
> change-id: 20241028-fix-noisy-debug-calls-a6d6185be705
> 
> Best regards,


-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Stefan Kerkmann]

Hi Ahmad,

On 28.10.24 17:44, Ahmad Fatoum wrote:
> Hi,
> 
> On 28.10.24 17:17, Stefan Kerkmann wrote:
>> These two patches are the outcome of an investigation why loading a
>> fitimage from an eMMC took nearly 7s - the sheer amount of generated
>> debugging messages slowed down the system by a factor of ~21 with
>> KConfig options:
>>
>> 	CONFIG_COMPILE_LOGLEVEL=7
>> 	CONFIG_DEFAULT_LOGLEVEL=6
>>
>> Which is the current default combination for barebox.
>>
>> Before:
>>
>> 	Booting entry 'system0'
>> 	FIT: Reading time: 6722 ms
>>
>> After:
>>
>> 	Booting entry 'system0'
>> 	FIT: Reading time: 324 ms
> 
> This is the time with these two patches applied or with
> compile log level changed?
> 

This is the time with both patches applied and the mentioned default log levels.

Cheers,
Stefan

> Cheers,
> Ahmad
> 
>>
>> Signed-off-by: Stefan Kerkmann <s.kerkmann@pengutronix.de>
>> ---
>> Stefan Kerkmann (2):
>>       block: downgrade noisy debug calls to verbose debug
>>       fs: ramfs: downgrade noisy debug calls to verbose debug
>>
>>  common/block.c |  4 ++--
>>  fs/ramfs.c     | 10 +++++-----
>>  2 files changed, 7 insertions(+), 7 deletions(-)
>> ---
>> base-commit: 59658c877bcc605fe3ca36653b4f40f57856b81a
>> change-id: 20241028-fix-noisy-debug-calls-a6d6185be705
>>
>> Best regards,
> 
> 

-- 
Pengutronix e.K.                       | Stefan Kerkmann             |
Steuerwalder Str. 21                   | https://www.pengutronix.de/ |
31137 Hildesheim, Germany              | Phone: +49-5121-206917-128  |
Amtsgericht Hildesheim, HRA 2686       | Fax:   +49-5121-206917-9    |

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Sascha Hauer]

On Mon, Oct 28, 2024 at 05:17:00PM +0100, Stefan Kerkmann wrote:
> These two patches are the outcome of an investigation why loading a
> fitimage from an eMMC took nearly 7s - the sheer amount of generated
> debugging messages slowed down the system by a factor of ~21 with
> KConfig options:
> 
> 	CONFIG_COMPILE_LOGLEVEL=7
> 	CONFIG_DEFAULT_LOGLEVEL=6
> 
> Which is the current default combination for barebox.

This is not the default combination. The default is:

CONFIG_COMPILE_LOGLEVEL=6
CONFIG_DEFAULT_LOGLEVEL=7

The rationale is:

Do not compile in debug messages by default (CONFIG_COMPILE_LOGLEVEL=6)
unless DEBUG is defined in a source file. When DEBUG is defined then make
sure the messages are printed (CONFIG_DEFAULT_LOGLEVEL=7).

There are tons of debug messages throughout the code which normally
shouldn't be compiled into the binay.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Ahmad Fatoum]

Hello Sascha,

On 29.10.24 14:33, Sascha Hauer wrote:
> On Mon, Oct 28, 2024 at 05:17:00PM +0100, Stefan Kerkmann wrote:
>> These two patches are the outcome of an investigation why loading a
>> fitimage from an eMMC took nearly 7s - the sheer amount of generated
>> debugging messages slowed down the system by a factor of ~21 with
>> KConfig options:
>>
>> 	CONFIG_COMPILE_LOGLEVEL=7
>> 	CONFIG_DEFAULT_LOGLEVEL=6
>>
>> Which is the current default combination for barebox.
> 
> This is not the default combination. The default is:
> 
> CONFIG_COMPILE_LOGLEVEL=6
> CONFIG_DEFAULT_LOGLEVEL=7
> 
> The rationale is:
> 
> Do not compile in debug messages by default (CONFIG_COMPILE_LOGLEVEL=6)
> unless DEBUG is defined in a source file. When DEBUG is defined then make
> sure the messages are printed (CONFIG_DEFAULT_LOGLEVEL=7).
> 
> There are tons of debug messages throughout the code which normally
> shouldn't be compiled into the binay.

These debug messages are overly verbose though. >13 messages (and thus
allocations) per read MMC block isn't useful.

Cheers,
Ahmad

> 
> Sascha
> 


-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Stefan Kerkmann]

Hi Sascha,

On 29.10.24 14:33, Sascha Hauer wrote:
> On Mon, Oct 28, 2024 at 05:17:00PM +0100, Stefan Kerkmann wrote:
>> These two patches are the outcome of an investigation why loading a
>> fitimage from an eMMC took nearly 7s - the sheer amount of generated
>> debugging messages slowed down the system by a factor of ~21 with
>> KConfig options:
>>
>> 	CONFIG_COMPILE_LOGLEVEL=7
>> 	CONFIG_DEFAULT_LOGLEVEL=6
>>
>> Which is the current default combination for barebox.
> 
> This is not the default combination. The default is:
> 
> CONFIG_COMPILE_LOGLEVEL=6
> CONFIG_DEFAULT_LOGLEVEL=7
> 

Oh! You are right, I totally mixed that up.

> The rationale is:
> 
> Do not compile in debug messages by default (CONFIG_COMPILE_LOGLEVEL=6)
> unless DEBUG is defined in a source file. When DEBUG is defined then make
> sure the messages are printed (CONFIG_DEFAULT_LOGLEVEL=7).
> 
> There are tons of debug messages throughout the code which normally
> shouldn't be compiled into the binay.
> 

When triaging a problem I like to gather a good overview by generally enabling
all debugging messages. But the important bits would drown in the block/ramfs
messages. So I would still argue that it is worthwhile to downgrade the level to
verbose debug.

Cheers,
Stefan

> Sascha
> 

-- 
Pengutronix e.K.                       | Stefan Kerkmann             |
Steuerwalder Str. 21                   | https://www.pengutronix.de/ |
31137 Hildesheim, Germany              | Phone: +49-5121-206917-128  |
Amtsgericht Hildesheim, HRA 2686       | Fax:   +49-5121-206917-9    |

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Sascha Hauer]

On Mon, 28 Oct 2024 17:17:00 +0100, Stefan Kerkmann wrote:
> These two patches are the outcome of an investigation why loading a
> fitimage from an eMMC took nearly 7s - the sheer amount of generated
> debugging messages slowed down the system by a factor of ~21 with
> KConfig options:
> 
> 	CONFIG_COMPILE_LOGLEVEL=7
> 	CONFIG_DEFAULT_LOGLEVEL=6
> 
> [...]

Applied, thanks!

[1/2] block: downgrade noisy debug calls to verbose debug
      https://git.pengutronix.de/cgit/barebox/commit/?id=e3c8e1efda5b (link may not be stable)
[2/2] fs: ramfs: downgrade noisy debug calls to verbose debug
      https://git.pengutronix.de/cgit/barebox/commit/?id=958909804650 (link may not be stable)

Best regards,
-- 
Sascha Hauer <s.hauer@pengutronix.de>

Re: [PATCH 0/2] downgrade noisy debug calls in block devices and ramfs

[Sascha Hauer]

On Tue, Oct 29, 2024 at 03:12:59PM +0100, Stefan Kerkmann wrote:
> Hi Sascha,
> 
> On 29.10.24 14:33, Sascha Hauer wrote:
> > On Mon, Oct 28, 2024 at 05:17:00PM +0100, Stefan Kerkmann wrote:
> >> These two patches are the outcome of an investigation why loading a
> >> fitimage from an eMMC took nearly 7s - the sheer amount of generated
> >> debugging messages slowed down the system by a factor of ~21 with
> >> KConfig options:
> >>
> >> 	CONFIG_COMPILE_LOGLEVEL=7
> >> 	CONFIG_DEFAULT_LOGLEVEL=6
> >>
> >> Which is the current default combination for barebox.
> > 
> > This is not the default combination. The default is:
> > 
> > CONFIG_COMPILE_LOGLEVEL=6
> > CONFIG_DEFAULT_LOGLEVEL=7
> > 
> 
> Oh! You are right, I totally mixed that up.
> 
> > The rationale is:
> > 
> > Do not compile in debug messages by default (CONFIG_COMPILE_LOGLEVEL=6)
> > unless DEBUG is defined in a source file. When DEBUG is defined then make
> > sure the messages are printed (CONFIG_DEFAULT_LOGLEVEL=7).
> > 
> > There are tons of debug messages throughout the code which normally
> > shouldn't be compiled into the binay.
> > 
> 
> When triaging a problem I like to gather a good overview by generally enabling
> all debugging messages. But the important bits would drown in the block/ramfs
> messages. So I would still argue that it is worthwhile to downgrade the level to
> verbose debug.

Yes, indeed. We should prefer pr_vdebug/dev_vdbg in hotpaths.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |