[PATCH] ACPI / EC: Remove non-standard log emphasis

[PATCH] ACPI / EC: Remove non-standard log emphasis

[Scot Doyle]

Remove unusual pr_info() visual emphasis introduced in ad479e7f47ca
"ACPI / EC: Introduce STARTED/STOPPED flags to replace BLOCKED flag".

Signed-off-by: Scot Doyle <lkml14@scotdoyle.com>
---
 drivers/acpi/ec.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index 982b67f..857175e 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -680,7 +680,7 @@ static void acpi_ec_start(struct acpi_ec *ec, bool resuming)
 		/* Enable GPE for event processing (SCI_EVT=1) */
 		if (!resuming)
 			acpi_ec_submit_request(ec);
-		pr_info("+++++ EC started +++++\n");
+		pr_info("EC started\n");
 	}
 	spin_unlock_irqrestore(&ec->lock, flags);
 }
@@ -712,7 +712,7 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
 			acpi_ec_complete_request(ec);
 		clear_bit(EC_FLAGS_STARTED, &ec->flags);
 		clear_bit(EC_FLAGS_STOPPED, &ec->flags);
-		pr_info("+++++ EC stopped +++++\n");
+		pr_info("EC stopped\n");
 	}
 	spin_unlock_irqrestore(&ec->lock, flags);
 }
-- 
2.2.1

Re: [PATCH] ACPI / EC: Remove non-standard log emphasis

[Rafael J. Wysocki]

On Sunday, February 15, 2015 07:43:08 PM Scot Doyle wrote:
> Remove unusual pr_info() visual emphasis introduced in ad479e7f47ca
> "ACPI / EC: Introduce STARTED/STOPPED flags to replace BLOCKED flag".
> 
> Signed-off-by: Scot Doyle <lkml14@scotdoyle.com>

Applied, thanks!

> ---
>  drivers/acpi/ec.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
> index 982b67f..857175e 100644
> --- a/drivers/acpi/ec.c
> +++ b/drivers/acpi/ec.c
> @@ -680,7 +680,7 @@ static void acpi_ec_start(struct acpi_ec *ec, bool resuming)
>  		/* Enable GPE for event processing (SCI_EVT=1) */
>  		if (!resuming)
>  			acpi_ec_submit_request(ec);
> -		pr_info("+++++ EC started +++++\n");
> +		pr_info("EC started\n");
>  	}
>  	spin_unlock_irqrestore(&ec->lock, flags);
>  }
> @@ -712,7 +712,7 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
>  			acpi_ec_complete_request(ec);
>  		clear_bit(EC_FLAGS_STARTED, &ec->flags);
>  		clear_bit(EC_FLAGS_STOPPED, &ec->flags);
> -		pr_info("+++++ EC stopped +++++\n");
> +		pr_info("EC stopped\n");
>  	}
>  	spin_unlock_irqrestore(&ec->lock, flags);
>  }
> 

-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

RE: [PATCH] ACPI / EC: Remove non-standard log emphasis

[Zheng, Lv]

Hi,

> From: Rafael J. Wysocki [mailto:rjw@rjwysocki.net]
> Sent: Wednesday, February 18, 2015 2:19 PM
> To: Scot Doyle
> Cc: Zheng, Lv; linux-acpi@vger.kernel.org; linux-kernel@vger.kernel.org
> Subject: Re: [PATCH] ACPI / EC: Remove non-standard log emphasis
> 
> On Sunday, February 15, 2015 07:43:08 PM Scot Doyle wrote:
> > Remove unusual pr_info() visual emphasis introduced in ad479e7f47ca
> > "ACPI / EC: Introduce STARTED/STOPPED flags to replace BLOCKED flag".
> >
> > Signed-off-by: Scot Doyle <lkml14@scotdoyle.com>
> 
> Applied, thanks!
> 
> > ---
> >  drivers/acpi/ec.c | 4 ++--
> >  1 file changed, 2 insertions(+), 2 deletions(-)
> >
> > diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
> > index 982b67f..857175e 100644
> > --- a/drivers/acpi/ec.c
> > +++ b/drivers/acpi/ec.c
> > @@ -680,7 +680,7 @@ static void acpi_ec_start(struct acpi_ec *ec, bool resuming)
> >  		/* Enable GPE for event processing (SCI_EVT=1) */
> >  		if (!resuming)
> >  			acpi_ec_submit_request(ec);
> > -		pr_info("+++++ EC started +++++\n");
> > +		pr_info("EC started\n");
> >  	}
> >  	spin_unlock_irqrestore(&ec->lock, flags);
> >  }
> > @@ -712,7 +712,7 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
> >  			acpi_ec_complete_request(ec);
> >  		clear_bit(EC_FLAGS_STARTED, &ec->flags);
> >  		clear_bit(EC_FLAGS_STOPPED, &ec->flags);
> > -		pr_info("+++++ EC stopped +++++\n");
> > +		pr_info("EC stopped\n");
> >  	}
> >  	spin_unlock_irqrestore(&ec->lock, flags);
> >  }
> >

I was using "+++++"/"#####"/"*****" to filter different EC log entries which makes debugging easier.
And, if we changed this from pr_info into pr_debug, then we will have nothing in the suspend/resume logs for the EC device.
While there are plenty of such log entries for each of other devices.
So I really doubt what's the meaning of such a change.
Could it improve anything or just make debugging more difficult for developers?

Thanks and best regards
-Lv


> 
> --
> I speak only for myself.
> Rafael J. Wysocki, Intel Open Source Technology Center.

RE: [PATCH] ACPI / EC: Remove non-standard log emphasis

[Zheng, Lv]

Hi,

> From: Zheng, Lv
> Sent: Wednesday, February 25, 2015 4:42 PM
> 
> Hi,
> 
> > From: Rafael J. Wysocki [mailto:rjw@rjwysocki.net]
> > Sent: Wednesday, February 18, 2015 2:19 PM
> > To: Scot Doyle
> > Cc: Zheng, Lv; linux-acpi@vger.kernel.org; linux-kernel@vger.kernel.org
> > Subject: Re: [PATCH] ACPI / EC: Remove non-standard log emphasis
> >
> > On Sunday, February 15, 2015 07:43:08 PM Scot Doyle wrote:
> > > Remove unusual pr_info() visual emphasis introduced in ad479e7f47ca
> > > "ACPI / EC: Introduce STARTED/STOPPED flags to replace BLOCKED flag".
> > >
> > > Signed-off-by: Scot Doyle <lkml14@scotdoyle.com>
> >
> > Applied, thanks!
> >
> > > ---
> > >  drivers/acpi/ec.c | 4 ++--
> > >  1 file changed, 2 insertions(+), 2 deletions(-)
> > >
> > > diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
> > > index 982b67f..857175e 100644
> > > --- a/drivers/acpi/ec.c
> > > +++ b/drivers/acpi/ec.c
> > > @@ -680,7 +680,7 @@ static void acpi_ec_start(struct acpi_ec *ec, bool resuming)
> > >  		/* Enable GPE for event processing (SCI_EVT=1) */
> > >  		if (!resuming)
> > >  			acpi_ec_submit_request(ec);
> > > -		pr_info("+++++ EC started +++++\n");
> > > +		pr_info("EC started\n");
> > >  	}
> > >  	spin_unlock_irqrestore(&ec->lock, flags);
> > >  }
> > > @@ -712,7 +712,7 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
> > >  			acpi_ec_complete_request(ec);
> > >  		clear_bit(EC_FLAGS_STARTED, &ec->flags);
> > >  		clear_bit(EC_FLAGS_STOPPED, &ec->flags);
> > > -		pr_info("+++++ EC stopped +++++\n");
> > > +		pr_info("EC stopped\n");
> > >  	}
> > >  	spin_unlock_irqrestore(&ec->lock, flags);
> > >  }
> > >
> 
> I was using "+++++"/"#####"/"*****" to filter different EC log entries which makes debugging easier.
> And, if we changed this from pr_info into pr_debug, then we will have nothing in the suspend/resume logs for the EC device.
> While there are plenty of such log entries for each of other devices.
> So I really doubt what's the meaning of such a change.
> Could it improve anything or just make debugging more difficult for developers?

IMO, it's better to introduce such kind of code in the head of ec.c:

#ifdef DEBUG_FILTER
#define EC_LOG_DEV "+++++"
#define EC_LOG_CMD "*****"
#define EC_LOG_EVT "#####"
...
#else
#define EC_LOG_DEV
#define EC_LOG_CMD
#define EC_LOG_EVT
#endif

And wrap the pr_info, pr_debug using filter enabled new macros - ec_info, ec_debug so that we won't see the filters in the normal dmesg output and the filters are still available for the developers.

Thanks and best regards
-Lv

> 
> Thanks and best regards
> -Lv
> 
> 
> >
> > --
> > I speak only for myself.
> > Rafael J. Wysocki, Intel Open Source Technology Center.

RE: [PATCH] ACPI / EC: Remove non-standard log emphasis

[Scot Doyle]

On Wed, 25 Feb 2015, Zheng, Lv wrote:
...
> > I was using "+++++"/"#####"/"*****" to filter different EC log entries which makes debugging easier.
> > And, if we changed this from pr_info into pr_debug, then we will have nothing in the suspend/resume logs for the EC device.
> > While there are plenty of such log entries for each of other devices.
> > So I really doubt what's the meaning of such a change.
> > Could it improve anything or just make debugging more difficult for developers?
> 
> IMO, it's better to introduce such kind of code in the head of ec.c:
> 
> #ifdef DEBUG_FILTER
> #define EC_LOG_DEV "+++++"
> #define EC_LOG_CMD "*****"
> #define EC_LOG_EVT "#####"
> ...
> #else
> #define EC_LOG_DEV
> #define EC_LOG_CMD
> #define EC_LOG_EVT
> #endif
> 
> And wrap the pr_info, pr_debug using filter enabled new macros - ec_info, ec_debug so that we won't see the filters in the normal dmesg output and the filters are still available for the developers.
> 
> Thanks and best regards
> -Lv

I agree, would you be willing to submit it?

Re: [PATCH] ACPI / EC: Remove non-standard log emphasis

[Rafael J. Wysocki]

On Wednesday, February 25, 2015 03:01:08 PM Scot Doyle wrote:
> On Wed, 25 Feb 2015, Zheng, Lv wrote:
> ...
> > > I was using "+++++"/"#####"/"*****" to filter different EC log entries which makes debugging easier.
> > > And, if we changed this from pr_info into pr_debug, then we will have nothing in the suspend/resume logs for the EC device.
> > > While there are plenty of such log entries for each of other devices.
> > > So I really doubt what's the meaning of such a change.
> > > Could it improve anything or just make debugging more difficult for developers?
> > 
> > IMO, it's better to introduce such kind of code in the head of ec.c:
> > 
> > #ifdef DEBUG_FILTER
> > #define EC_LOG_DEV "+++++"
> > #define EC_LOG_CMD "*****"
> > #define EC_LOG_EVT "#####"
> > ...
> > #else
> > #define EC_LOG_DEV
> > #define EC_LOG_CMD
> > #define EC_LOG_EVT
> > #endif
> > 
> > And wrap the pr_info, pr_debug using filter enabled new macros - ec_info, ec_debug so that we won't see the filters in the normal dmesg output and the filters are still available for the developers.
> > 
> > Thanks and best regards
> > -Lv
> 
> I agree, would you be willing to submit it?

Yes, sounds good to me too!


-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

RE: [PATCH] ACPI / EC: Remove non-standard log emphasis

[Zheng, Lv]

Hi,

> From: Rafael J. Wysocki [mailto:rjw@rjwysocki.net]
> Sent: Thursday, February 26, 2015 6:56 AM
> 
> On Wednesday, February 25, 2015 03:01:08 PM Scot Doyle wrote:
> > On Wed, 25 Feb 2015, Zheng, Lv wrote:
> > ...
> > > > I was using "+++++"/"#####"/"*****" to filter different EC log entries which makes debugging easier.
> > > > And, if we changed this from pr_info into pr_debug, then we will have nothing in the suspend/resume logs for the EC device.
> > > > While there are plenty of such log entries for each of other devices.
> > > > So I really doubt what's the meaning of such a change.
> > > > Could it improve anything or just make debugging more difficult for developers?
> > >
> > > IMO, it's better to introduce such kind of code in the head of ec.c:
> > >
> > > #ifdef DEBUG_FILTER
> > > #define EC_LOG_DEV "+++++"
> > > #define EC_LOG_CMD "*****"
> > > #define EC_LOG_EVT "#####"
> > > ...
> > > #else
> > > #define EC_LOG_DEV
> > > #define EC_LOG_CMD
> > > #define EC_LOG_EVT
> > > #endif
> > >
> > > And wrap the pr_info, pr_debug using filter enabled new macros - ec_info, ec_debug so that we won't see the filters in the
> normal dmesg output and the filters are still available for the developers.
> > >
> > > Thanks and best regards
> > > -Lv
> >
> > I agree, would you be willing to submit it?
> 
> Yes, sounds good to me too!

OK. Let me try it and send the revised one after testing.

Thanks and best regards
-Lv

> 
> 
> --
> I speak only for myself.
> Rafael J. Wysocki, Intel Open Source Technology Center.

[PATCH 0/2] ACPI / EC: Enhance logging/debugging.

[Lv Zheng]

This patchset enhances logging/debugging support in EC driver.

Lv Zheng (2):
  ACPI / EC: Cleanup logging/debugging splitter support.
  ACPI / EC: Add GPE reference counting debugging messages.

 drivers/acpi/ec.c |  120 +++++++++++++++++++++++++++++++++++++----------------
 1 file changed, 84 insertions(+), 36 deletions(-)

-- 
1.7.10

[PATCH 1/2] ACPI / EC: Cleanup logging/debugging splitter support.

[Lv Zheng]

This patch refines logging/debugging splitter support so that when DEBUG is
disabled, splitters won't be visible in the kernel logs while they are
still available for developers when DEBUG is enabled.

This patch also refines the splitters to mark the following handling
process boundaries:
  +++++: boundary of driver starting/stopping
         boundary of IRQ storming
  =====: boundary of transaction advancement
  *****: boundary of EC command
         boundary of EC query
  #####: boundary of EC _Qxx evaluation

The following 2 log entries are originally logged using pr_info() in order
to be used as the boot/suspend/resume log entries for the EC device, this
patch also restores them to pr_info() logging level:
 ACPI : EC: EC started
 ACPI : EC: EC stopped

In this patch, one log entry around "Polling quirk" is converted into
ec_dbg_raw() which doesn't contain the boundary marker.

Signed-off-by: Lv Zheng <lv.zheng@intel.com>
---
 drivers/acpi/ec.c |  108 ++++++++++++++++++++++++++++++++++++-----------------
 1 file changed, 74 insertions(+), 34 deletions(-)

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index a8dd2f7..07426c8 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -137,6 +137,48 @@ static int EC_FLAGS_CLEAR_ON_RESUME; /* Needs acpi_ec_clear() on boot/resume */
 static int EC_FLAGS_QUERY_HANDSHAKE; /* Needs QR_EC issued when SCI_EVT set */
 
 /* --------------------------------------------------------------------------
+ *                           Logging/Debugging
+ * -------------------------------------------------------------------------- */
+
+/*
+ * Splitters used by the developers to track the boundary of the EC
+ * handling processes.
+ */
+#ifdef DEBUG
+#define EC_DBG_SEP	" "
+#define EC_DBG_DRV	"+++++"
+#define EC_DBG_STM	"====="
+#define EC_DBG_REQ	"*****"
+#define EC_DBG_EVT	"#####"
+#else
+#define EC_DBG_SEP	""
+#define EC_DBG_DRV
+#define EC_DBG_STM
+#define EC_DBG_REQ
+#define EC_DBG_EVT
+#endif
+
+#define ec_log_raw(fmt, ...) \
+	pr_info(fmt "\n", ##__VA_ARGS__)
+#define ec_dbg_raw(fmt, ...) \
+	pr_debug(fmt "\n", ##__VA_ARGS__)
+#define ec_log(filter, fmt, ...) \
+	ec_log_raw(filter EC_DBG_SEP fmt EC_DBG_SEP filter, ##__VA_ARGS__)
+#define ec_dbg(filter, fmt, ...) \
+	ec_dbg_raw(filter EC_DBG_SEP fmt EC_DBG_SEP filter, ##__VA_ARGS__)
+
+#define ec_log_drv(fmt, ...) \
+	ec_log(EC_DBG_DRV, fmt, ##__VA_ARGS__)
+#define ec_dbg_drv(fmt, ...) \
+	ec_dbg(EC_DBG_DRV, fmt, ##__VA_ARGS__)
+#define ec_dbg_stm(fmt, ...) \
+	ec_dbg(EC_DBG_STM, fmt, ##__VA_ARGS__)
+#define ec_dbg_req(fmt, ...) \
+	ec_dbg(EC_DBG_REQ, fmt, ##__VA_ARGS__)
+#define ec_dbg_evt(fmt, ...) \
+	ec_dbg(EC_DBG_EVT, fmt, ##__VA_ARGS__)
+
+/* --------------------------------------------------------------------------
  *                           Device Flags
  * -------------------------------------------------------------------------- */
 
@@ -159,14 +201,14 @@ static inline u8 acpi_ec_read_status(struct acpi_ec *ec)
 {
 	u8 x = inb(ec->command_addr);
 
-	pr_debug("EC_SC(R) = 0x%2.2x "
-		 "SCI_EVT=%d BURST=%d CMD=%d IBF=%d OBF=%d\n",
-		 x,
-		 !!(x & ACPI_EC_FLAG_SCI),
-		 !!(x & ACPI_EC_FLAG_BURST),
-		 !!(x & ACPI_EC_FLAG_CMD),
-		 !!(x & ACPI_EC_FLAG_IBF),
-		 !!(x & ACPI_EC_FLAG_OBF));
+	ec_dbg_raw("EC_SC(R) = 0x%2.2x "
+		   "SCI_EVT=%d BURST=%d CMD=%d IBF=%d OBF=%d",
+		   x,
+		   !!(x & ACPI_EC_FLAG_SCI),
+		   !!(x & ACPI_EC_FLAG_BURST),
+		   !!(x & ACPI_EC_FLAG_CMD),
+		   !!(x & ACPI_EC_FLAG_IBF),
+		   !!(x & ACPI_EC_FLAG_OBF));
 	return x;
 }
 
@@ -175,20 +217,20 @@ static inline u8 acpi_ec_read_data(struct acpi_ec *ec)
 	u8 x = inb(ec->data_addr);
 
 	ec->curr->timestamp = jiffies;
-	pr_debug("EC_DATA(R) = 0x%2.2x\n", x);
+	ec_dbg_raw("EC_DATA(R) = 0x%2.2x", x);
 	return x;
 }
 
 static inline void acpi_ec_write_cmd(struct acpi_ec *ec, u8 command)
 {
-	pr_debug("EC_SC(W) = 0x%2.2x\n", command);
+	ec_dbg_raw("EC_SC(W) = 0x%2.2x", command);
 	outb(command, ec->command_addr);
 	ec->curr->timestamp = jiffies;
 }
 
 static inline void acpi_ec_write_data(struct acpi_ec *ec, u8 data)
 {
-	pr_debug("EC_DATA(W) = 0x%2.2x\n", data);
+	ec_dbg_raw("EC_DATA(W) = 0x%2.2x", data);
 	outb(data, ec->data_addr);
 	ec->curr->timestamp = jiffies;
 }
@@ -240,7 +282,7 @@ static inline void acpi_ec_enable_gpe(struct acpi_ec *ec, bool open)
 		 * software need to manually trigger a pseudo GPE event on
 		 * EN=1 writes.
 		 */
-		pr_debug("***** Polling quirk *****\n");
+		ec_dbg_raw("Polling quirk");
 		advance_transaction(ec);
 	}
 }
@@ -299,7 +341,7 @@ static void acpi_ec_set_storm(struct acpi_ec *ec, u8 flag)
 {
 	if (!test_bit(flag, &ec->flags)) {
 		acpi_ec_disable_gpe(ec, false);
-		pr_debug("+++++ Polling enabled +++++\n");
+		ec_dbg_drv("Polling enabled");
 		set_bit(flag, &ec->flags);
 	}
 }
@@ -309,7 +351,7 @@ static void acpi_ec_clear_storm(struct acpi_ec *ec, u8 flag)
 	if (test_bit(flag, &ec->flags)) {
 		clear_bit(flag, &ec->flags);
 		acpi_ec_enable_gpe(ec, false);
-		pr_debug("+++++ Polling disabled +++++\n");
+		ec_dbg_drv("Polling disabled");
 	}
 }
 
@@ -335,7 +377,7 @@ static bool acpi_ec_submit_flushable_request(struct acpi_ec *ec)
 static void acpi_ec_submit_query(struct acpi_ec *ec)
 {
 	if (!test_and_set_bit(EC_FLAGS_QUERY_PENDING, &ec->flags)) {
-		pr_debug("***** Event started *****\n");
+		ec_dbg_req("Event started");
 		schedule_work(&ec->work);
 	}
 }
@@ -344,7 +386,7 @@ static void acpi_ec_complete_query(struct acpi_ec *ec)
 {
 	if (ec->curr->command == ACPI_EC_COMMAND_QUERY) {
 		clear_bit(EC_FLAGS_QUERY_PENDING, &ec->flags);
-		pr_debug("***** Event stopped *****\n");
+		ec_dbg_req("Event stopped");
 	}
 }
 
@@ -366,8 +408,8 @@ static void advance_transaction(struct acpi_ec *ec)
 	u8 status;
 	bool wakeup = false;
 
-	pr_debug("===== %s (%d) =====\n",
-		 in_interrupt() ? "IRQ" : "TASK", smp_processor_id());
+	ec_dbg_stm("%s (%d)", in_interrupt() ? "IRQ" : "TASK",
+		   smp_processor_id());
 	/*
 	 * By always clearing STS before handling all indications, we can
 	 * ensure a hardware STS 0->1 change after this clearing can always
@@ -390,8 +432,8 @@ static void advance_transaction(struct acpi_ec *ec)
 				if (t->rlen == t->ri) {
 					t->flags |= ACPI_EC_COMMAND_COMPLETE;
 					if (t->command == ACPI_EC_COMMAND_QUERY)
-						pr_debug("***** Command(%s) hardware completion *****\n",
-							 acpi_ec_cmd_string(t->command));
+						ec_dbg_req("Command(%s) hardware completion",
+							   acpi_ec_cmd_string(t->command));
 					wakeup = true;
 				}
 			} else
@@ -410,8 +452,8 @@ static void advance_transaction(struct acpi_ec *ec)
 			acpi_ec_complete_query(ec);
 			t->rdata[t->ri++] = 0x00;
 			t->flags |= ACPI_EC_COMMAND_COMPLETE;
-			pr_debug("***** Command(%s) software completion *****\n",
-				 acpi_ec_cmd_string(t->command));
+			ec_dbg_req("Command(%s) software completion",
+				   acpi_ec_cmd_string(t->command));
 			wakeup = true;
 		} else if ((status & ACPI_EC_FLAG_IBF) == 0) {
 			acpi_ec_write_cmd(ec, t->command);
@@ -504,16 +546,14 @@ static int acpi_ec_transaction_unlocked(struct acpi_ec *ec,
 	}
 	/* following two actions should be kept atomic */
 	ec->curr = t;
-	pr_debug("***** Command(%s) started *****\n",
-		 acpi_ec_cmd_string(t->command));
+	ec_dbg_req("Command(%s) started", acpi_ec_cmd_string(t->command));
 	start_transaction(ec);
 	spin_unlock_irqrestore(&ec->lock, tmp);
 	ret = ec_poll(ec);
 	spin_lock_irqsave(&ec->lock, tmp);
 	if (t->irq_count == ec_storm_threshold)
 		acpi_ec_clear_storm(ec, EC_FLAGS_COMMAND_STORM);
-	pr_debug("***** Command(%s) stopped *****\n",
-		 acpi_ec_cmd_string(t->command));
+	ec_dbg_req("Command(%s) stopped", acpi_ec_cmd_string(t->command));
 	ec->curr = NULL;
 	/* Disable GPE for command processing (IBF=0/OBF=1) */
 	acpi_ec_complete_request(ec);
@@ -676,11 +716,11 @@ static void acpi_ec_start(struct acpi_ec *ec, bool resuming)
 
 	spin_lock_irqsave(&ec->lock, flags);
 	if (!test_and_set_bit(EC_FLAGS_STARTED, &ec->flags)) {
-		pr_debug("+++++ Starting EC +++++\n");
+		ec_dbg_drv("Starting EC");
 		/* Enable GPE for event processing (SCI_EVT=1) */
 		if (!resuming)
 			acpi_ec_submit_request(ec);
-		pr_debug("EC started\n");
+		ec_log_drv("EC started");
 	}
 	spin_unlock_irqrestore(&ec->lock, flags);
 }
@@ -702,7 +742,7 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
 
 	spin_lock_irqsave(&ec->lock, flags);
 	if (acpi_ec_started(ec)) {
-		pr_debug("+++++ Stopping EC +++++\n");
+		ec_dbg_drv("Stopping EC");
 		set_bit(EC_FLAGS_STOPPED, &ec->flags);
 		spin_unlock_irqrestore(&ec->lock, flags);
 		wait_event(ec->wait, acpi_ec_stopped(ec));
@@ -712,7 +752,7 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
 			acpi_ec_complete_request(ec);
 		clear_bit(EC_FLAGS_STARTED, &ec->flags);
 		clear_bit(EC_FLAGS_STOPPED, &ec->flags);
-		pr_debug("EC stopped\n");
+		ec_log_drv("EC stopped");
 	}
 	spin_unlock_irqrestore(&ec->lock, flags);
 }
@@ -824,12 +864,12 @@ static void acpi_ec_run(void *cxt)
 
 	if (!handler)
 		return;
-	pr_debug("##### Query(0x%02x) started #####\n", handler->query_bit);
+	ec_dbg_evt("Query(0x%02x) started", handler->query_bit);
 	if (handler->func)
 		handler->func(handler->data);
 	else if (handler->handle)
 		acpi_evaluate_object(handler->handle, NULL, NULL, NULL);
-	pr_debug("##### Query(0x%02x) stopped #####\n", handler->query_bit);
+	ec_dbg_evt("Query(0x%02x) stopped", handler->query_bit);
 	acpi_ec_put_query_handler(handler);
 }
 
@@ -861,8 +901,8 @@ static int acpi_ec_query(struct acpi_ec *ec, u8 *data)
 		if (value == handler->query_bit) {
 			/* have custom handler for this bit */
 			handler = acpi_ec_get_query_handler(handler);
-			pr_debug("##### Query(0x%02x) scheduled #####\n",
-				 handler->query_bit);
+			ec_dbg_evt("Query(0x%02x) scheduled",
+				   handler->query_bit);
 			status = acpi_os_execute((handler->func) ?
 				OSL_NOTIFY_HANDLER : OSL_GPE_HANDLER,
 				acpi_ec_run, handler);
-- 
1.7.10

Re: [PATCH 1/2] ACPI / EC: Cleanup logging/debugging splitter support.

[Joe Perches]

On Fri, 2015-02-27 at 14:48 +0800, Lv Zheng wrote:
> This patch refines logging/debugging splitter support so that when DEBUG is
> disabled, splitters won't be visible in the kernel logs while they are
> still available for developers when DEBUG is enabled.
> 
> This patch also refines the splitters to mark the following handling
> process boundaries:
>   +++++: boundary of driver starting/stopping
>          boundary of IRQ storming
>   =====: boundary of transaction advancement
>   *****: boundary of EC command
>          boundary of EC query
>   #####: boundary of EC _Qxx evaluation

trivia:

> diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
[]
>  /* --------------------------------------------------------------------------
> + *                           Logging/Debugging
> + * -------------------------------------------------------------------------- */
> +
> +/*
> + * Splitters used by the developers to track the boundary of the EC
> + * handling processes.
> + */

It'd be nice to comment/document these 3 letter descriptions
a bit better here in the source code.

> +#ifdef DEBUG
> +#define EC_DBG_SEP	" "
> +#define EC_DBG_DRV	"+++++"
> +#define EC_DBG_STM	"====="
> +#define EC_DBG_REQ	"*****"
> +#define EC_DBG_EVT	"#####"

Maybe:

#define EC_DBG_SEP	" "
#define EC_DBG_DRV	"+++++"		/* drivers start/stop */
#define EC_DBG_STM	"====="		/* irq storm */
#define EC_DBG_REQ	"*****"		/* ec command boundary */
#define EC_DBG_EVT	"#####"		/* EC _Qxx evaluation */
> 

[PATCH 2/2] ACPI / EC: Add GPE reference counting debugging messages.

[Lv Zheng]

This patch enhances debugging with the GPE reference count messages added.

This kind of log entries can be used by the platform validators to validate
if there is an EC transaction broken because of firmware/driver bugs.

No functional changes.

Signed-off-by: Lv Zheng <lv.zheng@intel.com>
---
 drivers/acpi/ec.c |   12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index 07426c8..a362f20 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -177,6 +177,8 @@ static int EC_FLAGS_QUERY_HANDSHAKE; /* Needs QR_EC issued when SCI_EVT set */
 	ec_dbg(EC_DBG_REQ, fmt, ##__VA_ARGS__)
 #define ec_dbg_evt(fmt, ...) \
 	ec_dbg(EC_DBG_EVT, fmt, ##__VA_ARGS__)
+#define ec_dbg_ref(ec, fmt, ...) \
+	ec_dbg_raw("%lu: " fmt, ec->reference_count, ## __VA_ARGS__)
 
 /* --------------------------------------------------------------------------
  *                           Device Flags
@@ -544,6 +546,7 @@ static int acpi_ec_transaction_unlocked(struct acpi_ec *ec,
 		ret = -EINVAL;
 		goto unlock;
 	}
+	ec_dbg_ref(ec, "Increase command");
 	/* following two actions should be kept atomic */
 	ec->curr = t;
 	ec_dbg_req("Command(%s) started", acpi_ec_cmd_string(t->command));
@@ -557,6 +560,7 @@ static int acpi_ec_transaction_unlocked(struct acpi_ec *ec,
 	ec->curr = NULL;
 	/* Disable GPE for command processing (IBF=0/OBF=1) */
 	acpi_ec_complete_request(ec);
+	ec_dbg_ref(ec, "Decrease command");
 unlock:
 	spin_unlock_irqrestore(&ec->lock, tmp);
 	return ret;
@@ -718,8 +722,10 @@ static void acpi_ec_start(struct acpi_ec *ec, bool resuming)
 	if (!test_and_set_bit(EC_FLAGS_STARTED, &ec->flags)) {
 		ec_dbg_drv("Starting EC");
 		/* Enable GPE for event processing (SCI_EVT=1) */
-		if (!resuming)
+		if (!resuming) {
 			acpi_ec_submit_request(ec);
+			ec_dbg_ref(ec, "Increase driver");
+		}
 		ec_log_drv("EC started");
 	}
 	spin_unlock_irqrestore(&ec->lock, flags);
@@ -748,8 +754,10 @@ static void acpi_ec_stop(struct acpi_ec *ec, bool suspending)
 		wait_event(ec->wait, acpi_ec_stopped(ec));
 		spin_lock_irqsave(&ec->lock, flags);
 		/* Disable GPE for event processing (SCI_EVT=1) */
-		if (!suspending)
+		if (!suspending) {
 			acpi_ec_complete_request(ec);
+			ec_dbg_ref(ec, "Decrease driver");
+		}
 		clear_bit(EC_FLAGS_STARTED, &ec->flags);
 		clear_bit(EC_FLAGS_STOPPED, &ec->flags);
 		ec_log_drv("EC stopped");
-- 
1.7.10

Re: [PATCH 0/2] ACPI / EC: Enhance logging/debugging.

[Rafael J. Wysocki]

On Friday, February 27, 2015 02:48:07 PM Lv Zheng wrote:
> This patchset enhances logging/debugging support in EC driver.
> 
> Lv Zheng (2):
>   ACPI / EC: Cleanup logging/debugging splitter support.
>   ACPI / EC: Add GPE reference counting debugging messages.
> 
>  drivers/acpi/ec.c |  120 +++++++++++++++++++++++++++++++++++++----------------
>  1 file changed, 84 insertions(+), 36 deletions(-)

Queued up for 4.1, thanks!

-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.