regarding ata_msg_*()

regarding ata_msg_*()

[Tejun Heo]

Hello, Jeff, Borislav.

I looked through the ata_msg_*() changes and read Donald Becker's 
message about network driver message control.  This is needed facility 
and I agree with general direction, but I have slightly different ideas 
about details.

We currently have the following message categories.

	ATA_MSG_DRV	= 0x0001,
	ATA_MSG_INFO	= 0x0002,
	ATA_MSG_PROBE	= 0x0004,
	ATA_MSG_WARN	= 0x0008,
	ATA_MSG_MALLOC	= 0x0010,
	ATA_MSG_CTL	= 0x0020,
	ATA_MSG_INTR	= 0x0040,
	ATA_MSG_ERR	= 0x0080,

* I have no idea what CTL means or why DRV is used in ata_dev_disable().

* By default, ATA_MSG_INFO is turned off, which means 
ata_dev_configure() doesn't print anything about newly detected and 
configured device, which isn't good (BTW, why is @print_info completely 
ignored in that function?  It's needed.  We don't want to print those 
messages when we're just revalidating devices.)  Unfortunately, if I 
enable ATA_MSG_INFO, I enable some of function ENTER/EXIT messages, too. 
  Bah...

* In ata_dev_configure(), some ENTER/EXIT messages are INFO while others 
are PROBE.

* In ata_dev_read_id(), ENTER message is CTL, what is CTL?  What makes 
ata_port_flush_task() and ata_dev_read_id() share CTL?  And, why are 
flush#2/EXIT messages CTL while ENTER/flush#1 are left as DPRINTK?

All of the above problems are introduced during single sweep conversion 
over libata-core.c.  It might be that it simply was a bad sweep, but 
with the current ambiguous definitions, I don't think things will be any 
better when different people try to use those message types on various LLDs.

So, please make things *much* simpler.  I think it's overly elaborate to 
categorize normal (non-debug) messages by message types.  In my 
experience, such categorization usually ends up mis-categorization - you 
know, "Is this PROBE or CTL? who cares? make it INFO.  Is INFO debug or 
normal message?  WTF..."

IMHO, it's enough to have non-debug messages categorized by verbosity - 
CRIT, ERR, WARN and INFO and all of them enabled by default.  This also 
forces developers to suppress the urge to be whiny and refine their 
messages.  Maybe we can add one more level below INFO for 
slightly-verbose but not quite debug, but I think we're better off 
without it.

For debug messages, we probably need some categorization to separate LLD 
message from core messages and suppress command issue/completion debug 
messages unless strictly necessary, etc...  But, those categories MUST 
be made by necessities (e.g. issue/completion messages suffocates other 
messages, so they need separate slot.) not by some logical 
out-of-the-blue categorization.  Otherwise, we end up with categories 
which may be obvious to some but not so to others and things will get messy.

Thanks.

-- 
tejun

Re: regarding ata_msg_*()

[Borislav Petkov]

On Sun, Jun 25, 2006 at 09:21:13PM +0900, Tejun Heo wrote:

Morning,
 
> 	ATA_MSG_DRV	= 0x0001,
> 	ATA_MSG_INFO	= 0x0002,
> 	ATA_MSG_PROBE	= 0x0004,
> 	ATA_MSG_WARN	= 0x0008,
> 	ATA_MSG_MALLOC	= 0x0010,
> 	ATA_MSG_CTL	= 0x0020,
> 	ATA_MSG_INTR	= 0x0040,
> 	ATA_MSG_ERR	= 0x0080,
> 
> * I have no idea what CTL means or why DRV is used in ata_dev_disable().
> 
> * By default, ATA_MSG_INFO is turned off, which means 
> ata_dev_configure() doesn't print anything about newly detected and 
> configured device, which isn't good (BTW, why is @print_info completely 
> ignored in that function?  It's needed.  We don't want to print those 
> messages when we're just revalidating devices.)  Unfortunately, if I 
> enable ATA_MSG_INFO, I enable some of function ENTER/EXIT messages, too. 
>  Bah...

These all are different debugging levels which I proposed leaning on D. Becker's
mail, see linux-ide archives from 25 Aug 2005. I agree that the debugging levels
are somewhat "off-course" but this was not the main concern when sending the
patches. Instead, we aimed first at the complete conversion to the new scheme 
and then reajusting dbbg levels, so this is that...
 
> * In ata_dev_read_id(), ENTER message is CTL, what is CTL?  What makes 
In this mail it says also what CTL means and since nobody opposed to that I went
on preparing the patches.
> ata_port_flush_task() and ata_dev_read_id() share CTL?  And, why are 
> flush#2/EXIT messages CTL while ENTER/flush#1 are left as DPRINTK?
My bad, it seems I've missed those, but there are some cases like
ata_dev_classify(), for ex., where you simply
don't have an access to ata_dev or ata_port struct in order to issue a message
according to the msg_enable status so I left those out for further discussion
concerning replacement.

> All of the above problems are introduced during single sweep conversion 
> over libata-core.c.  It might be that it simply was a bad sweep, but 
> with the current ambiguous definitions, I don't think things will be any 
> better when different people try to use those message types on various LLDs.
> 
> So, please make things *much* simpler.  I think it's overly elaborate to 
> categorize normal (non-debug) messages by message types.  In my 
> experience, such categorization usually ends up mis-categorization - you 
> know, "Is this PROBE or CTL? who cares? make it INFO.  Is INFO debug or 
> normal message?  WTF..."
> 
> IMHO, it's enough to have non-debug messages categorized by verbosity - 
> CRIT, ERR, WARN and INFO and all of them enabled by default.  This also 
> forces developers to suppress the urge to be whiny and refine their 
> messages.  Maybe we can add one more level below INFO for 
> slightly-verbose but not quite debug, but I think we're better off 
> without it.
> 
> For debug messages, we probably need some categorization to separate LLD 
> message from core messages and suppress command issue/completion debug 
> messages unless strictly necessary, etc...  But, those categories MUST 
> be made by necessities (e.g. issue/completion messages suffocates other 
> messages, so they need separate slot.) not by some logical 
> out-of-the-blue categorization.  Otherwise, we end up with categories 
> which may be obvious to some but not so to others and things will get messy.

I guess you're right about the laziness/carelessness (no insinuations
 whatsoever :)) factor with developers but I still 
think it is a good thing to have different debugging levels for different
message semantics and messages origin like interrupts, mem allocation, hardware probing,
etc. I think, though, it would be better to have the debugging scheme running
first and then rehash and reconfigure which debugging levels are appropriate and
enough for libata-dev...

Regards,
    Boris.

		
___________________________________________________________ 
Telefonate ohne weitere Kosten vom PC zum PC: http://messenger.yahoo.de

Re: regarding ata_msg_*()

[Tejun Heo]

Hello, Borislav.

Borislav Petkov wrote:
>> * By default, ATA_MSG_INFO is turned off, which means 
>> ata_dev_configure() doesn't print anything about newly detected and 
>> configured device, which isn't good (BTW, why is @print_info completely 
>> ignored in that function?  It's needed.  We don't want to print those 
>> messages when we're just revalidating devices.)  Unfortunately, if I 
>> enable ATA_MSG_INFO, I enable some of function ENTER/EXIT messages, too. 
>>  Bah...
> 
> These all are different debugging levels which I proposed leaning on D. Becker's
> mail, see linux-ide archives from 25 Aug 2005. I agree that the debugging levels
> are somewhat "off-course" but this was not the main concern when sending the
> patches. Instead, we aimed first at the complete conversion to the new scheme 
> and then reajusting dbbg levels, so this is that...

I'm sorry that I'm whining now not back then, but better late than 
never, I guess.

>> * In ata_dev_read_id(), ENTER message is CTL, what is CTL?  What makes 
> In this mail it says also what CTL means and since nobody opposed to that I went
> on preparing the patches.

I'll look that up, but whatever it is, please make it apparent in the 
code - please add some comments after constant definitions at the very 
least.

[--snip--]
> I guess you're right about the laziness/carelessness (no insinuations
>  whatsoever :)) factor with developers but I still 

I would be one of the first ones being lazy/careless.  Insinuations 
welcomed.  :-)

> think it is a good thing to have different debugging levels for different
> message semantics and messages origin like interrupts, mem allocation, hardware probing,

To some degree, I agree but for example you mentioned mem allocation as 
one of the categories.  The thing is that libata almost never allocates 
anything during normal operation.  Even hotplug/unplugs are performed 
w/o any memory allocation.  Allocations only occur during driver 
attachment and if allocation fails during that, there's nothing much to 
do than printing error message and giving up - no need for separate 
category.

I'm not saying debug message categorization is unnecessary.  It will be 
useful, but let's do it only on as-needed basis.  IMHO, that will lead 
to the least amount of confusion.

> etc. I think, though, it would be better to have the debugging scheme running
> first and then rehash and reconfigure which debugging levels are appropriate and
> enough for libata-dev...

My suggestion is to keep the current (pre-msg_enable) model for the 
first conversion and categorize debug messages further after that.  So, 
message categories will be...

ATA_MSG_ERR
ATA_MSG_WARN
ATA_MSG_INFO
-------------> all above are enabled by default
ATA_MSG_DEBUG
ATA_MSG_VDEBUG

Then, you have 1-to-1 mapping w/ the existing messages.  You can simply 
incorporate message enabled tests into ata_*_printk() functions and the 
conversion would be trivial.

After that's complete, we can diversify ATA_MSG_DEBUG and ATA_MSG_VDEBUG 
by separating out chatty ones out.  e.g. you can separate out SG 
mapping/unmapping (including padding) debug messages, which produce 
massive amount of logs when enabled, into ATA_MSG_SG or something. 
After several such separations, debug messages should be quite 
manageable && the categories wouldn't be too elaborate.

Thanks.

-- 
tejun

Re: regarding ata_msg_*()

[Borislav Petkov]

On Mon, Jun 26, 2006 at 05:00:39PM +0900, Tejun Heo wrote:

Hi Tejun,

<snip>
> My suggestion is to keep the current (pre-msg_enable) model for the 
> first conversion and categorize debug messages further after that.  So, 
> message categories will be...
> 
> ATA_MSG_ERR
> ATA_MSG_WARN
> ATA_MSG_INFO
> -------------> all above are enabled by default
> ATA_MSG_DEBUG
> ATA_MSG_VDEBUG
> 
> Then, you have 1-to-1 mapping w/ the existing messages.  You can simply 
> incorporate message enabled tests into ata_*_printk() functions and the 
> conversion would be trivial.
>
> After that's complete, we can diversify ATA_MSG_DEBUG and ATA_MSG_VDEBUG 
> by separating out chatty ones out.  e.g. you can separate out SG 
> mapping/unmapping (including padding) debug messages, which produce 
> massive amount of logs when enabled, into ATA_MSG_SG or something. 
> After several such separations, debug messages should be quite 
> manageable && the categories wouldn't be too elaborate.

Yes, this sounds logical, I like it, it really fits libata more but at the time
I made that msg classification I kinda wanted to stick closely to Becker's
initial implementation :). But you're perfectly right, this is the way to go so
I'll do that after reading what the others have to say. However, as I said
before, IMHO it would be of higher priority now to convert to this new scheme
and changing the dbg levels later would be trivial once we got all of libata
done.

Regards,
    Boris.

		
___________________________________________________________ 
Telefonate ohne weitere Kosten vom PC zum PC: http://messenger.yahoo.de

Re: regarding ata_msg_*()

[Tejun Heo]

Borislav Petkov wrote:
>> My suggestion is to keep the current (pre-msg_enable) model for the 
>> first conversion and categorize debug messages further after that.  So, 
>> message categories will be...
>>
>> ATA_MSG_ERR
>> ATA_MSG_WARN
>> ATA_MSG_INFO
>> -------------> all above are enabled by default
>> ATA_MSG_DEBUG
>> ATA_MSG_VDEBUG
>>
>> Then, you have 1-to-1 mapping w/ the existing messages.  You can simply 
>> incorporate message enabled tests into ata_*_printk() functions and the 
>> conversion would be trivial.
>>
>> After that's complete, we can diversify ATA_MSG_DEBUG and ATA_MSG_VDEBUG 
>> by separating out chatty ones out.  e.g. you can separate out SG 
>> mapping/unmapping (including padding) debug messages, which produce 
>> massive amount of logs when enabled, into ATA_MSG_SG or something. 
>> After several such separations, debug messages should be quite 
>> manageable && the categories wouldn't be too elaborate.
> 
> Yes, this sounds logical, I like it, it really fits libata more but at the time
> I made that msg classification I kinda wanted to stick closely to Becker's
> initial implementation :). But you're perfectly right, this is the way to go so
> I'll do that after reading what the others have to say. However, as I said
> before, IMHO it would be of higher priority now to convert to this new scheme
> and changing the dbg levels later would be trivial once we got all of libata
> done.

Jeff, what do you think?

Borislav, can you restore configuration messages in ata_dev_configure()? 
  Those messages need to be printed.

Thanks.

-- 
tejun

Re: regarding ata_msg_*()

[Jeff Garzik]

Tejun Heo wrote:
> ATA_MSG_ERR
> ATA_MSG_WARN
> ATA_MSG_INFO
> -------------> all above are enabled by default
> ATA_MSG_DEBUG
> ATA_MSG_VDEBUG


The current ATA_MSG_xxx were best-guesses, and only now, when the 
conversion patches begin to be merged, do we see how well those guesses 
match with reality.

I do agree that the above list matches the current code, but the 
ATA_MSG_xxx and Becker schemes are aimed more at verbosity+severity 
levels, than strictly severity levels.

<thinking aloud>  For libata, the best mapping might be

0: critical problems (errors)
1: non-critical, recovered problems or "troubling circumstances" (warnings)
2: terse info from exceptional events (probe, hotplug)
3: more verbose info about exceptional events (IDENTIFY hex values as 
shown today, sector count, features)
4: terse command-submit tracing
5: terse command-complete tracing
6: verbose hot path
7: function ENTER/EXIT tracing

Thus illustrating the general goals of (a) enabling fine-grained tracing 
of specific portions of libata, (b) ordering messages in order of 
severity, and (c) ordering messages by likelihood of producing tons of 
log spam.

Eventually we can use blktool to turn on terse command-complete tracing 
for a single SATA port, and not have to suffer the current log spam and 
coarseness that results from using today's #defines.

	Jeff

Re: regarding ata_msg_*()

[Tejun Heo]

Jeff Garzik wrote:
> Tejun Heo wrote:
>> ATA_MSG_ERR
>> ATA_MSG_WARN
>> ATA_MSG_INFO
>> -------------> all above are enabled by default
>> ATA_MSG_DEBUG
>> ATA_MSG_VDEBUG
> 
> The current ATA_MSG_xxx were best-guesses, and only now, when the 
> conversion patches begin to be merged, do we see how well those guesses 
> match with reality.
> 
> I do agree that the above list matches the current code, but the 
> ATA_MSG_xxx and Becker schemes are aimed more at verbosity+severity 
> levels, than strictly severity levels.

Yeap, agreed.

My point is that as we need selective message enabling, let's do it by 
first implementing 1:1 mapping and think about message types later.  As 
we already have ata_*_printk() wrappers, embedding ata_msg_*() and 
converting KERN_* to ATA_MSG_* should be enough.

> <thinking aloud>  For libata, the best mapping might be
> 
> 0: critical problems (errors)
> 1: non-critical, recovered problems or "troubling circumstances" (warnings)
> 2: terse info from exceptional events (probe, hotplug)
> 3: more verbose info about exceptional events (IDENTIFY hex values as 
> shown today, sector count, features)
> 4: terse command-submit tracing
> 5: terse command-complete tracing
> 6: verbose hot path
> 7: function ENTER/EXIT tracing
> 
> Thus illustrating the general goals of (a) enabling fine-grained tracing 
> of specific portions of libata, (b) ordering messages in order of 
> severity, and (c) ordering messages by likelihood of producing tons of 
> log spam.

Generally agreed.  I don't think your and my ideas are that different. 
Mine looks like..

ATA_MSG_ERR
ATA_MSG_WARNING
ATA_MSG_INFO	/* I think intial config msg should be in this cat */
(ATA_MSG_VINFO maybe) /* revalidation messages, EH progress... */
-- debug below here
ATA_MSG_DEBUG
ATA_MSG_VDEBUG
ATA_MSG_CMD	/* issue / completion */
ATA_MSG_SG	/* SG map/unmap handling */
ATA_MGS_TRACE	/* function enter/exit */

> Eventually we can use blktool to turn on terse command-complete tracing 
> for a single SATA port, and not have to suffer the current log spam and 
> coarseness that results from using today's #defines.

Yeah, we really need that.  I currently use /dev/hda as my root when I 
need to turn on those debug messages.  :-P

-- 
tejun