[libcamera-devel] libcamera: Add debug printouts

Message ID 20190111160737.25094-1-jacopo@jmondi.org
State Accepted
Headers show
Series
  • [libcamera-devel] libcamera: Add debug printouts
Related show

Commit Message

Jacopo Mondi Jan. 11, 2019, 4:07 p.m. UTC
Add a few debug printouts that help follow the library intialization
process: what pipeline handlers are registered, what media devices are
created, and which pipeline manager gets matches with the current
system.

The resulting output is the following, on IPU3 devices:
DBG pipeline_handler.cpp:119 Pipeline handler: "PipeHandlerVimc" registered
DBG pipeline_handler.cpp:119 Pipeline handler: "PipelineHandlerIPU3" registered
DBG device_enumerator.cpp:214 New media device: ipu3-imgu created from: /dev/media0
DBG device_enumerator.cpp:214 New media device: ipu3-cio2 created from: /dev/media1
DBG device_enumerator.cpp:255 Succesfull match for media device: ipu3-cio2
DBG device_enumerator.cpp:255 Succesfull match for media device: ipu3-imgu
DBG pipeline_handler.cpp:150 Pipeline handler: "PipelineHandlerIPU3" matched

Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>
---
 src/libcamera/device_enumerator.cpp | 8 +++++++-
 src/libcamera/pipeline_handler.cpp  | 5 ++++-
 2 files changed, 11 insertions(+), 2 deletions(-)

--
2.20.1

Comments

Kieran Bingham Jan. 14, 2019, 1:44 p.m. UTC | #1
Hi Jacopo,

On 11/01/2019 16:07, Jacopo Mondi wrote:
> Add a few debug printouts that help follow the library intialization
> process: what pipeline handlers are registered, what media devices are
> created, and which pipeline manager gets matches with the current
> system.

Great - I think this will be useful to have some visibility while
developing, and we can easily disable the DBG output when we add
LogLevel selection. (and we'll probably default it above the debug level
of course).


> 
> The resulting output is the following, on IPU3 devices:
> DBG pipeline_handler.cpp:119 Pipeline handler: "PipeHandlerVimc" registered
> DBG pipeline_handler.cpp:119 Pipeline handler: "PipelineHandlerIPU3" registered
> DBG device_enumerator.cpp:214 New media device: ipu3-imgu created from: /dev/media0
> DBG device_enumerator.cpp:214 New media device: ipu3-cio2 created from: /dev/media1
> DBG device_enumerator.cpp:255 Succesfull match for media device: ipu3-cio2
> DBG device_enumerator.cpp:255 Succesfull match for media device: ipu3-imgu
> DBG pipeline_handler.cpp:150 Pipeline handler: "PipelineHandlerIPU3" matched
> 
> Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>
> ---
>  src/libcamera/device_enumerator.cpp | 8 +++++++-
>  src/libcamera/pipeline_handler.cpp  | 5 ++++-
>  2 files changed, 11 insertions(+), 2 deletions(-)
> 
> diff --git a/src/libcamera/device_enumerator.cpp b/src/libcamera/device_enumerator.cpp
> index 0d18e75..c1ddd7c 100644
> --- a/src/libcamera/device_enumerator.cpp
> +++ b/src/libcamera/device_enumerator.cpp
> @@ -211,6 +211,9 @@ int DeviceEnumerator::addDevice(const std::string &devnode)
>  		return ret;
>  	}
> 
> +	LOG(Debug) << "New media device: " << media->driver()
> +		   << " created from: " << devnode;
> +
>  	/* Associate entities to device node paths. */
>  	for (MediaEntity *entity : media->entities()) {
>  		if (entity->deviceMajor() == 0 && entity->deviceMinor() == 0)
> @@ -248,8 +251,11 @@ MediaDevice *DeviceEnumerator::search(const DeviceMatch &dm) const
>  		if (dev->busy())
>  			continue;
> 
> -		if (dm.match(dev))
> +		if (dm.match(dev)) {
> +			LOG(Debug) << "Succesfull match for media device: "

s/Succesfull/Successful/

> +				   << dev->driver();
>  			return dev;
> +		}
>  	}
> 
>  	return nullptr;
> diff --git a/src/libcamera/pipeline_handler.cpp b/src/libcamera/pipeline_handler.cpp
> index ee76948..9299c28 100644
> --- a/src/libcamera/pipeline_handler.cpp
> +++ b/src/libcamera/pipeline_handler.cpp
> @@ -116,6 +116,7 @@ void PipelineHandlerFactory::registerType(const std::string &name,
>  		return;
>  	}
> 
> +	LOG(Debug) << "Pipeline handler: \"" << name << "\" registered";
>  	factories[name] = factory;
>  }
> 
> @@ -145,8 +146,10 @@ PipelineHandler *PipelineHandlerFactory::create(const std::string &name,
> 
>  	PipelineHandler *pipe = it->second->create();
> 
> -	if (pipe->match(enumerator))
> +	if (pipe->match(enumerator)) {
> +		LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";

(not for this patch - just ideas out loud)

Can/Should we make a function/macro called
	 quoted((os), (_s))

 which will do:

  os << ("\"" << (_s) << "\"")

LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
LOG(Debug) << "Pipeline handler: " << quoted(name) << " matched";


>  		return pipe;
> +	}
> 
>  	delete pipe;
>  	return nullptr;
> --
> 2.20.1
> 
> _______________________________________________
> libcamera-devel mailing list
> libcamera-devel@lists.libcamera.org
> https://lists.libcamera.org/listinfo/libcamera-devel
>
Laurent Pinchart Jan. 15, 2019, 2:02 a.m. UTC | #2
Hello,

On Monday, 14 January 2019 15:44:21 EET Kieran Bingham wrote:
> On 11/01/2019 16:07, Jacopo Mondi wrote:
> > Add a few debug printouts that help follow the library intialization
> > process: what pipeline handlers are registered, what media devices are
> > created, and which pipeline manager gets matches with the current
> > system.
> 
> Great - I think this will be useful to have some visibility while
> developing, and we can easily disable the DBG output when we add
> LogLevel selection. (and we'll probably default it above the debug level
> of course).
> 
> > The resulting output is the following, on IPU3 devices:
> > DBG pipeline_handler.cpp:119 Pipeline handler: "PipeHandlerVimc"
> > registered
> > DBG pipeline_handler.cpp:119 Pipeline handler: "PipelineHandlerIPU3"
> > registered DBG device_enumerator.cpp:214 New media device: ipu3-imgu
> > created from: /dev/media0 DBG device_enumerator.cpp:214 New media device:
> > ipu3-cio2 created from: /dev/media1 DBG device_enumerator.cpp:255
> > Succesfull match for media device: ipu3-cio2 DBG
> > device_enumerator.cpp:255 Succesfull match for media device: ipu3-imgu
> > DBG pipeline_handler.cpp:150 Pipeline handler: "PipelineHandlerIPU3"
> > matched
> > 
> > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>
> > ---
> > 
> >  src/libcamera/device_enumerator.cpp | 8 +++++++-
> >  src/libcamera/pipeline_handler.cpp  | 5 ++++-
> >  2 files changed, 11 insertions(+), 2 deletions(-)
> > 
> > diff --git a/src/libcamera/device_enumerator.cpp
> > b/src/libcamera/device_enumerator.cpp index 0d18e75..c1ddd7c 100644
> > --- a/src/libcamera/device_enumerator.cpp
> > +++ b/src/libcamera/device_enumerator.cpp
> > @@ -211,6 +211,9 @@ int DeviceEnumerator::addDevice(const std::string
> > &devnode)
> >  		return ret;
> >  	}
> > 
> > +	LOG(Debug) << "New media device: " << media->driver()
> > +		   << " created from: " << devnode;
> > +

Do we need the ":" ? This would print

New media device: uvcvideo created from: /dev/media0

Wouldn't the following be more readable ?

New media device "uvcvideo created from /dev/media0

That would be obtained by

	LOG(Debug) << "New media device \"" << media->driver()
		<< "\" created from " << devnode;

> >  	/* Associate entities to device node paths. */
> >  	for (MediaEntity *entity : media->entities()) {
> >  		if (entity->deviceMajor() == 0 && entity->deviceMinor() == 0)
> > @@ -248,8 +251,11 @@ MediaDevice *DeviceEnumerator::search(const
> > DeviceMatch &dm) const
> >  		if (dev->busy())
> >  			continue;
> > 
> > -		if (dm.match(dev))
> > +		if (dm.match(dev)) {
> > +			LOG(Debug) << "Succesfull match for media device: "
> 
> s/Succesfull/Successful/
> 
> > +				   << dev->driver();

Same here, I'd remove the ":".

> >  			return dev;
> > +		}
> >  	}
> >  	
> >  	return nullptr;
> > diff --git a/src/libcamera/pipeline_handler.cpp
> > b/src/libcamera/pipeline_handler.cpp index ee76948..9299c28 100644
> > --- a/src/libcamera/pipeline_handler.cpp
> > +++ b/src/libcamera/pipeline_handler.cpp
> > @@ -116,6 +116,7 @@ void PipelineHandlerFactory::registerType(const
> > std::string &name,
> >  		return;
> >  	}
> > 
> > +	LOG(Debug) << "Pipeline handler: \"" << name << "\" registered";

And here

	LOG(Debug) << "Registered pipeline handler \"" << name << "\"";

> >  	factories[name] = factory;
> >  }
> > 
> > @@ -145,8 +146,10 @@ PipelineHandler *PipelineHandlerFactory::create(const
> > std::string &name,
> >  	PipelineHandler *pipe = it->second->create();
> > 
> > -	if (pipe->match(enumerator))
> > +	if (pipe->match(enumerator)) {
> > +		LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";

And removing the ":" here too.

> (not for this patch - just ideas out loud)
> 
> Can/Should we make a function/macro called
> 	 quoted((os), (_s))
> 
>  which will do:
> 
>   os << ("\"" << (_s) << "\"")

I suppose this would be

#define quote(s)		"\"" << s << "\""

> LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
> LOG(Debug) << "Pipeline handler: " << quoted(name) << " matched";

Wouldn't it reduce readability by hiding a simple construct behind a macro ? I 
know it's tempting to avoid writing the escape sequence...

> >  		return pipe;
> > +	}
> > 
> >  	delete pipe;
> >  	return nullptr;

Reviewed-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com>
Kieran Bingham Jan. 15, 2019, 11 a.m. UTC | #3
On 15/01/2019 02:02, Laurent Pinchart wrote:
> Hello,

<snip>

>>>
>>> -	if (pipe->match(enumerator))
>>> +	if (pipe->match(enumerator)) {
>>> +		LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
> 
> And removing the ":" here too.
> 
>> (not for this patch - just ideas out loud)
>>
>> Can/Should we make a function/macro called
>> 	 quoted((os), (_s))
>>
>>  which will do:
>>
>>   os << ("\"" << (_s) << "\"")
> 
> I suppose this would be
> 
> #define quote(s)		"\"" << s << "\""

Ah yes - I was overcomplicating already :)

> 
>> LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
>> LOG(Debug) << "Pipeline handler: " << quoted(name) << " matched";
> 
> Wouldn't it reduce readability by hiding a simple construct behind a macro ? I 
> know it's tempting to avoid writing the escape sequence...

Does it? I guess it's subjective.

It is a simple construct yes, but IMO the escaping of the {"} hinders
readability more. A quick glance here:

  : \"" << name << "\" matched

could look like we are sending the string
  { name "\" matched } as if it was a path with backslashes or such...

(Yes I'm aware that the example above is taken slightly out of context,
and it was done so purposefully to represent 'a quick glance')...


Also a helper here would ensure that quotes are correctly terminated, as
demonstrated in Jacopo's patch f1caaaf387 ("libcamera: Debug printouts
fixes") which adds in a missing final "\"";

+	LOG(Debug) << "Successful match for media device \""
+		   << dev->driver() << "\"";

Although in that particular case - I think that log statement could have
been on one line where it would then be more obvious too.

	LOG(Debug) << "Successful match for media device "
		   << quoted(dev->driver());

Anyway - it was just an idea/suggestion, I'm not tied to it ...



>>>  		return pipe;
>>> +	}
>>>
>>>  	delete pipe;
>>>  	return nullptr;
> 
> Reviewed-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com>
>
Laurent Pinchart Jan. 15, 2019, 1:28 p.m. UTC | #4
Hi Kieran,

On Tuesday, 15 January 2019 13:00:50 EET Kieran Bingham wrote:
> On 15/01/2019 02:02, Laurent Pinchart wrote:
> > Hello,
> 
> <snip>
> 
> >>> -	if (pipe->match(enumerator))
> >>> +	if (pipe->match(enumerator)) {
> >>> +		LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
> > 
> > And removing the ":" here too.
> > 
> >> (not for this patch - just ideas out loud)
> >> 
> >> Can/Should we make a function/macro called
> >> 
> >> 	 quoted((os), (_s))
> >>  
> >>  which will do:
> >>   os << ("\"" << (_s) << "\"")
> > 
> > I suppose this would be
> > 
> > #define quote(s)		"\"" << s << "\""
> 
> Ah yes - I was overcomplicating already :)
> 
> >> LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
> >> LOG(Debug) << "Pipeline handler: " << quoted(name) << " matched";
> > 
> > Wouldn't it reduce readability by hiding a simple construct behind a macro
> > ? I know it's tempting to avoid writing the escape sequence...
> 
> Does it? I guess it's subjective.
> 
> It is a simple construct yes, but IMO the escaping of the {"} hinders
> 
> readability more. A quick glance here:
>   : \"" << name << "\" matched
> 
> could look like we are sending the string
>   { name "\" matched } as if it was a path with backslashes or such...
> 
> (Yes I'm aware that the example above is taken slightly out of context,
> and it was done so purposefully to represent 'a quick glance')...
> 
> 
> Also a helper here would ensure that quotes are correctly terminated, as
> demonstrated in Jacopo's patch f1caaaf387 ("libcamera: Debug printouts
> fixes") which adds in a missing final "\"";
> 
> +	LOG(Debug) << "Successful match for media device \""
> +		   << dev->driver() << "\"";
> 
> Although in that particular case - I think that log statement could have
> been on one line where it would then be more obvious too.
> 
> 	LOG(Debug) << "Successful match for media device "
> 		   << quoted(dev->driver());
> 
> Anyway - it was just an idea/suggestion, I'm not tied to it ...

If you submit a patch I won't reject it :-) I would however prefer a function 
instead of a macro, in order to avoid claiming such a generic name in the 
global namespace. One option would be, in log.h,

 	LogSeverity severity_;
 };
 
+namespace log {
+
+static inline std::string quoted(const std::string &name)
+{
+	return "\"" + name + "\"";
+}
+
+} /* namespace log */
+
 
 #define LOG(severity) LogMessage(__FILE__, __LINE__, Log##severity).stream()
 
(Whether we want a log namespace there is debatable). The function would be 
used as

	LOG(Debug) << "Print a quoted " << log::quoted(name);

I haven't studied whether there could be efficiency concerns due to string 
concatenation.

> >>>  		return pipe;
> >>> +	}
> >>> 
> >>>  	delete pipe;
> >>>  	return nullptr;
> > 
> > Reviewed-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com>
Laurent Pinchart Jan. 15, 2019, 1:37 p.m. UTC | #5
Hello again,

On Tuesday, 15 January 2019 15:28:45 EET Laurent Pinchart wrote:
> On Tuesday, 15 January 2019 13:00:50 EET Kieran Bingham wrote:
> > On 15/01/2019 02:02, Laurent Pinchart wrote:
> > > Hello,
> > 
> > <snip>
> > 
> > >>> -	if (pipe->match(enumerator))
> > >>> +	if (pipe->match(enumerator)) {
> > >>> +		LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
> > > 
> > > And removing the ":" here too.
> > > 
> > >> (not for this patch - just ideas out loud)
> > >> 
> > >> Can/Should we make a function/macro called
> > >> 
> > >> 	 quoted((os), (_s))
> > >>  
> > >>  which will do:
> > >>   os << ("\"" << (_s) << "\"")
> > > 
> > > I suppose this would be
> > > 
> > > #define quote(s)		"\"" << s << "\""
> > 
> > Ah yes - I was overcomplicating already :)
> > 
> > >> LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
> > >> LOG(Debug) << "Pipeline handler: " << quoted(name) << " matched";
> > > 
> > > Wouldn't it reduce readability by hiding a simple construct behind a
> > > macro
> > > ? I know it's tempting to avoid writing the escape sequence...
> > 
> > Does it? I guess it's subjective.
> > 
> > It is a simple construct yes, but IMO the escaping of the {"} hinders
> > 
> > readability more. A quick glance here:
> >   : \"" << name << "\" matched
> > 
> > could look like we are sending the string
> > 
> >   { name "\" matched } as if it was a path with backslashes or such...
> > 
> > (Yes I'm aware that the example above is taken slightly out of context,
> > and it was done so purposefully to represent 'a quick glance')...
> > 
> > 
> > Also a helper here would ensure that quotes are correctly terminated, as
> > demonstrated in Jacopo's patch f1caaaf387 ("libcamera: Debug printouts
> > fixes") which adds in a missing final "\"";
> > 
> > +	LOG(Debug) << "Successful match for media device \""
> > +		   << dev->driver() << "\"";
> > 
> > Although in that particular case - I think that log statement could have
> > been on one line where it would then be more obvious too.
> > 
> > 	LOG(Debug) << "Successful match for media device "
> > 	
> > 		   << quoted(dev->driver());
> > 
> > Anyway - it was just an idea/suggestion, I'm not tied to it ...
> 
> If you submit a patch I won't reject it :-) I would however prefer a
> function instead of a macro, in order to avoid claiming such a generic name
> in the global namespace. One option would be, in log.h,
> 
>  	LogSeverity severity_;
>  };
> 
> +namespace log {
> +
> +static inline std::string quoted(const std::string &name)
> +{
> +	return "\"" + name + "\"";
> +}
> +
> +} /* namespace log */
> +
> 
>  #define LOG(severity) LogMessage(__FILE__, __LINE__,
> Log##severity).stream()
> 
> (Whether we want a log namespace there is debatable). The function would be
> used as
> 
> 	LOG(Debug) << "Print a quoted " << log::quoted(name);
> 
> I haven't studied whether there could be efficiency concerns due to string
> concatenation.

I forgot to mention that a simple solution to all this could be to use single 
quotes instead of double quotes.

	LOG(Debug) << "Print a quoted '" << name << "'";

> > >>>  		return pipe;
> > >>> 
> > >>> +	}
> > >>> 
> > >>>  	delete pipe;
> > >>>  	return nullptr;
> > > 
> > > Reviewed-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com>

Patch

diff --git a/src/libcamera/device_enumerator.cpp b/src/libcamera/device_enumerator.cpp
index 0d18e75..c1ddd7c 100644
--- a/src/libcamera/device_enumerator.cpp
+++ b/src/libcamera/device_enumerator.cpp
@@ -211,6 +211,9 @@  int DeviceEnumerator::addDevice(const std::string &devnode)
 		return ret;
 	}

+	LOG(Debug) << "New media device: " << media->driver()
+		   << " created from: " << devnode;
+
 	/* Associate entities to device node paths. */
 	for (MediaEntity *entity : media->entities()) {
 		if (entity->deviceMajor() == 0 && entity->deviceMinor() == 0)
@@ -248,8 +251,11 @@  MediaDevice *DeviceEnumerator::search(const DeviceMatch &dm) const
 		if (dev->busy())
 			continue;

-		if (dm.match(dev))
+		if (dm.match(dev)) {
+			LOG(Debug) << "Succesfull match for media device: "
+				   << dev->driver();
 			return dev;
+		}
 	}

 	return nullptr;
diff --git a/src/libcamera/pipeline_handler.cpp b/src/libcamera/pipeline_handler.cpp
index ee76948..9299c28 100644
--- a/src/libcamera/pipeline_handler.cpp
+++ b/src/libcamera/pipeline_handler.cpp
@@ -116,6 +116,7 @@  void PipelineHandlerFactory::registerType(const std::string &name,
 		return;
 	}

+	LOG(Debug) << "Pipeline handler: \"" << name << "\" registered";
 	factories[name] = factory;
 }

@@ -145,8 +146,10 @@  PipelineHandler *PipelineHandlerFactory::create(const std::string &name,

 	PipelineHandler *pipe = it->second->create();

-	if (pipe->match(enumerator))
+	if (pipe->match(enumerator)) {
+		LOG(Debug) << "Pipeline handler: \"" << name << "\" matched";
 		return pipe;
+	}

 	delete pipe;
 	return nullptr;