| Message ID | 20210128090454.515268-1-jacopo@jmondi.org |
|---|---|
| State | Accepted |
| Headers | show |
| Series |
|
| Related | show |
Hi Jacopo, Thanks for your bikeshedding opportunity :-) On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote: > The current logging to track the status of a Request when running the > Android camera HAL provide the following information: > > When a Request is queued to libcamera: > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > When a Request completes: > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > The queueing of a Request reports the number of streams it contains > while the completion of a Request reports the address of the associated > cookie. > > This makes very hard to keep track of what Requests have completed, as > the logging associated with a queue/complete event does not allow to identify > a Request easily. > > Add two more printouts to make it easier to track a Request life cycle. > > The result looks like the following trace: > I like the improvement, but I would alter it slightly. I think having the cookie value is the real value here as it makes it possible to trace a request. > Request request.cpp:92 Created request - cookie: 138508601718368 > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams I would remove this print to increase signal to noise. If the number of streams really are important I would do a 1/n thing on the line below. If the line is keept I would also print the cookie. > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) I would add the cookie. > ... > ... > Request request.cpp:268 Request has completed - cookie: 138508601718368 > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams I would add the cookie and possibly s/with 1 streams// Bikeshedding is fun but take only what you like. At the end if all lines have the cookie you can also take my, Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> > --- > src/android/camera_device.cpp | 3 +++ > src/libcamera/request.cpp | 2 ++ > 2 files changed, 5 insertions(+) > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > index a9634f4e4198..513f000b1854 100644 > --- a/src/android/camera_device.cpp > +++ b/src/android/camera_device.cpp > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > status = CAMERA3_BUFFER_STATUS_ERROR; > } > > + LOG(HAL, Debug) << "Request completed by libcamera with " > + << descriptor->numBuffers_ << " streams"; > + > /* > * \todo The timestamp used for the metadata is currently always taken > * from the first buffer (which may be the first stream) in the Request. > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > index a68684ef9fd3..e561ce1d5d0e 100644 > --- a/src/libcamera/request.cpp > +++ b/src/libcamera/request.cpp > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > metadata_ = new ControlList(controls::controls); > > LIBCAMERA_TRACEPOINT(request_construct, this); > + > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > } > > Request::~Request() > -- > 2.30.0 > > _______________________________________________ > libcamera-devel mailing list > libcamera-devel@lists.libcamera.org > https://lists.libcamera.org/listinfo/libcamera-devel
Hi Niklas, On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote: > Hi Jacopo, > > Thanks for your bikeshedding opportunity :-) > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote: > > The current logging to track the status of a Request when running the > > Android camera HAL provide the following information: > > > > When a Request is queued to libcamera: > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > When a Request completes: > > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > > > The queueing of a Request reports the number of streams it contains > > while the completion of a Request reports the address of the associated > > cookie. > > > > This makes very hard to keep track of what Requests have completed, as > > the logging associated with a queue/complete event does not allow to identify > > a Request easily. > > > > Add two more printouts to make it easier to track a Request life cycle. > > > > The result looks like the following trace: > > > > I like the improvement, but I would alter it slightly. I think having > the cookie value is the real value here as it makes it possible to trace > a request. > > > Request request.cpp:92 Created request - cookie: 138508601718368 > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > I would remove this print to increase signal to noise. If the number of > streams really are important I would do a 1/n thing on the line below. > If the line is keept I would also print the cookie. I'm sorry I didn't fully get this one. What do you mean with "a 1/n thing on the line below" ? Also, I think identifying how many streams the request contains is relevant. > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) > > I would add the cookie. > > > ... > > ... > > Request request.cpp:268 Request has completed - cookie: 138508601718368 > > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams > > I would add the cookie and possibly s/with 1 streams// If we remove the stream count and add the cookie, I would then rather drop the printout in camera_device.cpp completely, as it will provide the exact same information that the one in request.cpp provides... > > Bikeshedding is fun but take only what you like. At the end if all lines > have the cookie you can also take my, > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> > > --- > > src/android/camera_device.cpp | 3 +++ > > src/libcamera/request.cpp | 2 ++ > > 2 files changed, 5 insertions(+) > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > > index a9634f4e4198..513f000b1854 100644 > > --- a/src/android/camera_device.cpp > > +++ b/src/android/camera_device.cpp > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > > status = CAMERA3_BUFFER_STATUS_ERROR; > > } > > > > + LOG(HAL, Debug) << "Request completed by libcamera with " > > + << descriptor->numBuffers_ << " streams"; > > + > > /* > > * \todo The timestamp used for the metadata is currently always taken > > * from the first buffer (which may be the first stream) in the Request. > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > > index a68684ef9fd3..e561ce1d5d0e 100644 > > --- a/src/libcamera/request.cpp > > +++ b/src/libcamera/request.cpp > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > > metadata_ = new ControlList(controls::controls); > > > > LIBCAMERA_TRACEPOINT(request_construct, this); > > + > > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > > } > > > > Request::~Request() > > -- > > 2.30.0 > > > > _______________________________________________ > > libcamera-devel mailing list > > libcamera-devel@lists.libcamera.org > > https://lists.libcamera.org/listinfo/libcamera-devel > > -- > Regards, > Niklas Söderlund
Hi Jacopo, On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote: > Hi Niklas, > > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote: > > Hi Jacopo, > > > > Thanks for your bikeshedding opportunity :-) > > > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote: > > > The current logging to track the status of a Request when running the > > > Android camera HAL provide the following information: > > > > > > When a Request is queued to libcamera: > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > When a Request completes: > > > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > > > > > The queueing of a Request reports the number of streams it contains > > > while the completion of a Request reports the address of the associated > > > cookie. > > > > > > This makes very hard to keep track of what Requests have completed, as > > > the logging associated with a queue/complete event does not allow to identify > > > a Request easily. > > > > > > Add two more printouts to make it easier to track a Request life cycle. > > > > > > The result looks like the following trace: > > > > > > > I like the improvement, but I would alter it slightly. I think having > > the cookie value is the real value here as it makes it possible to trace > > a request. > > > > > Request request.cpp:92 Created request - cookie: 138508601718368 > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > I would remove this print to increase signal to noise. If the number of > > streams really are important I would do a 1/n thing on the line below. > > If the line is keept I would also print the cookie. > > I'm sorry I didn't fully get this one. What do you mean with "a 1/n > thing on the line below" ? > > Also, I think identifying how many streams the request contains is > relevant. I was thinking of if it make sens to instead of HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) Have something like, HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) I find the later more compact while at the same time providing more information in a situation where you have to debug from a log file. > > > > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > I would add the cookie. > > > > > ... > > > ... > > > Request request.cpp:268 Request has completed - cookie: 138508601718368 > > > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams > > > > I would add the cookie and possibly s/with 1 streams// > > If we remove the stream count and add the cookie, I would then rather > drop the printout in camera_device.cpp completely, as it will provide > the exact same information that the one in request.cpp provides... Is it a problem that the same information is printed at different levels? I like to see such things as it allows me to from a log file track how a request moved thru the layers. Also if I'm only interested in debugging a specific component maybe I have a LIBCAMERA_LOG_LEVELS=HAL:0 or such set? In either case as stated in my first reply this is all bikeshedding so I don't feel strongly about any of it :-) > > > > > Bikeshedding is fun but take only what you like. At the end if all lines > > have the cookie you can also take my, > > > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > > > > > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> > > > --- > > > src/android/camera_device.cpp | 3 +++ > > > src/libcamera/request.cpp | 2 ++ > > > 2 files changed, 5 insertions(+) > > > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > > > index a9634f4e4198..513f000b1854 100644 > > > --- a/src/android/camera_device.cpp > > > +++ b/src/android/camera_device.cpp > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > > > status = CAMERA3_BUFFER_STATUS_ERROR; > > > } > > > > > > + LOG(HAL, Debug) << "Request completed by libcamera with " > > > + << descriptor->numBuffers_ << " streams"; > > > + > > > /* > > > * \todo The timestamp used for the metadata is currently always taken > > > * from the first buffer (which may be the first stream) in the Request. > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > > > index a68684ef9fd3..e561ce1d5d0e 100644 > > > --- a/src/libcamera/request.cpp > > > +++ b/src/libcamera/request.cpp > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > > > metadata_ = new ControlList(controls::controls); > > > > > > LIBCAMERA_TRACEPOINT(request_construct, this); > > > + > > > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > > > } > > > > > > Request::~Request() > > > -- > > > 2.30.0 > > > > > > _______________________________________________ > > > libcamera-devel mailing list > > > libcamera-devel@lists.libcamera.org > > > https://lists.libcamera.org/listinfo/libcamera-devel > > > > -- > > Regards, > > Niklas Söderlund
Hi Jacopo, On Thu, Jan 28, 2021 at 10:04:54AM +0100, Jacopo Mondi wrote: > The current logging to track the status of a Request when running the > Android camera HAL provide the following information: > > When a Request is queued to libcamera: > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > When a Request completes: > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > The queueing of a Request reports the number of streams it contains > while the completion of a Request reports the address of the associated > cookie. > > This makes very hard to keep track of what Requests have completed, as > the logging associated with a queue/complete event does not allow to identify > a Request easily. > > Add two more printouts to make it easier to track a Request life cycle. > > The result looks like the following trace: > > Request request.cpp:92 Created request - cookie: 138508601718368 > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) > ... > ... > Request request.cpp:268 Request has completed - cookie: 138508601718368 > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> Ooh, good idea! Reviewed-by: Paul Elder <paul.elder@ideasonboard.com> > --- > src/android/camera_device.cpp | 3 +++ > src/libcamera/request.cpp | 2 ++ > 2 files changed, 5 insertions(+) > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > index a9634f4e4198..513f000b1854 100644 > --- a/src/android/camera_device.cpp > +++ b/src/android/camera_device.cpp > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > status = CAMERA3_BUFFER_STATUS_ERROR; > } > > + LOG(HAL, Debug) << "Request completed by libcamera with " > + << descriptor->numBuffers_ << " streams"; > + > /* > * \todo The timestamp used for the metadata is currently always taken > * from the first buffer (which may be the first stream) in the Request. > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > index a68684ef9fd3..e561ce1d5d0e 100644 > --- a/src/libcamera/request.cpp > +++ b/src/libcamera/request.cpp > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > metadata_ = new ControlList(controls::controls); > > LIBCAMERA_TRACEPOINT(request_construct, this); > + > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > } > > Request::~Request() > -- > 2.30.0 > > _______________________________________________ > libcamera-devel mailing list > libcamera-devel@lists.libcamera.org > https://lists.libcamera.org/listinfo/libcamera-devel
Hi Niklas, On Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote: > Hi Jacopo, > > On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote: > > Hi Niklas, > > > > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote: > > > Hi Jacopo, > > > > > > Thanks for your bikeshedding opportunity :-) > > > > > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote: > > > > The current logging to track the status of a Request when running the > > > > Android camera HAL provide the following information: > > > > > > > > When a Request is queued to libcamera: > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > > > When a Request completes: > > > > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > > > > > > > The queueing of a Request reports the number of streams it contains > > > > while the completion of a Request reports the address of the associated > > > > cookie. > > > > > > > > This makes very hard to keep track of what Requests have completed, as > > > > the logging associated with a queue/complete event does not allow to identify > > > > a Request easily. > > > > > > > > Add two more printouts to make it easier to track a Request life cycle. > > > > > > > > The result looks like the following trace: > > > > > > > > > > I like the improvement, but I would alter it slightly. I think having > > > the cookie value is the real value here as it makes it possible to trace > > > a request. > > > > > > > Request request.cpp:92 Created request - cookie: 138508601718368 > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > I would remove this print to increase signal to noise. If the number of > > > streams really are important I would do a 1/n thing on the line below. > > > If the line is keept I would also print the cookie. > > > > I'm sorry I didn't fully get this one. What do you mean with "a 1/n > > thing on the line below" ? > > > > Also, I think identifying how many streams the request contains is > > relevant. > > I was thinking of if it make sens to instead of > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > Have something like, > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > I find the later more compact while at the same time providing more > information in a situation where you have to debug from a log file. So, that might be a matter of tastes, but: 1) I try to avoid creating too long log lines I always run with terminals one side to the other, spanning more than the usual 80-cols is ok, as it's reasonable to suppose most people have larger screens nowadays, but I think we should try to be compact to ease debug/development 2) I try to separate information in lines, as log can be filtered, either by using libcamera log infrastructure or by piping the usual unix tools. In your example, reporting the same cookie in two lines to me add noise and makes debug more confusing than having information separated on multiple lines. I can easily filter/grep on lines I'm interested in, and I prefer one more line to parse than parsing information on a single long line Might be a matter of tastes indeed > > > > > > > > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > > > I would add the cookie. > > > > > > > ... > > > > ... > > > > Request request.cpp:268 Request has completed - cookie: 138508601718368 > > > > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams > > > > > > I would add the cookie and possibly s/with 1 streams// > > > > If we remove the stream count and add the cookie, I would then rather > > drop the printout in camera_device.cpp completely, as it will provide > > the exact same information that the one in request.cpp provides... > > Is it a problem that the same information is printed at different > levels? I like to see such things as it allows me to from a log file > track how a request moved thru the layers. Also if I'm only interested > in debugging a specific component maybe I have a > LIBCAMERA_LOG_LEVELS=HAL:0 or such set? Ok addin the cookie to the request complete log > > In either case as stated in my first reply this is all bikeshedding so I > don't feel strongly about any of it :-) > > > > > > > > > Bikeshedding is fun but take only what you like. At the end if all lines > > > have the cookie you can also take my, > > > > > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> Thanks, I'll send a new version and I'll retain the tag, but please feel free to comment on that one as well. Thanks j > > > > > > > > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> > > > > --- > > > > src/android/camera_device.cpp | 3 +++ > > > > src/libcamera/request.cpp | 2 ++ > > > > 2 files changed, 5 insertions(+) > > > > > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > > > > index a9634f4e4198..513f000b1854 100644 > > > > --- a/src/android/camera_device.cpp > > > > +++ b/src/android/camera_device.cpp > > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > > > > status = CAMERA3_BUFFER_STATUS_ERROR; > > > > } > > > > > > > > + LOG(HAL, Debug) << "Request completed by libcamera with " > > > > + << descriptor->numBuffers_ << " streams"; > > > > + > > > > /* > > > > * \todo The timestamp used for the metadata is currently always taken > > > > * from the first buffer (which may be the first stream) in the Request. > > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > > > > index a68684ef9fd3..e561ce1d5d0e 100644 > > > > --- a/src/libcamera/request.cpp > > > > +++ b/src/libcamera/request.cpp > > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > > > > metadata_ = new ControlList(controls::controls); > > > > > > > > LIBCAMERA_TRACEPOINT(request_construct, this); > > > > + > > > > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > > > > } > > > > > > > > Request::~Request() > > > > -- > > > > 2.30.0 > > > > > > > > _______________________________________________ > > > > libcamera-devel mailing list > > > > libcamera-devel@lists.libcamera.org > > > > https://lists.libcamera.org/listinfo/libcamera-devel > > > > > > -- > > > Regards, > > > Niklas Söderlund > > -- > Regards, > Niklas Söderlund
Hi Jacopo, On 2021-02-02 12:40:56 +0100, Jacopo Mondi wrote: > Hi Niklas, > > On Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote: > > Hi Jacopo, > > > > On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote: > > > Hi Niklas, > > > > > > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote: > > > > Hi Jacopo, > > > > > > > > Thanks for your bikeshedding opportunity :-) > > > > > > > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote: > > > > > The current logging to track the status of a Request when running the > > > > > Android camera HAL provide the following information: > > > > > > > > > > When a Request is queued to libcamera: > > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > > > > > When a Request completes: > > > > > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > > > > > > > > > The queueing of a Request reports the number of streams it contains > > > > > while the completion of a Request reports the address of the associated > > > > > cookie. > > > > > > > > > > This makes very hard to keep track of what Requests have completed, as > > > > > the logging associated with a queue/complete event does not allow to identify > > > > > a Request easily. > > > > > > > > > > Add two more printouts to make it easier to track a Request life cycle. > > > > > > > > > > The result looks like the following trace: > > > > > > > > > > > > > I like the improvement, but I would alter it slightly. I think having > > > > the cookie value is the real value here as it makes it possible to trace > > > > a request. > > > > > > > > > Request request.cpp:92 Created request - cookie: 138508601718368 > > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > > > I would remove this print to increase signal to noise. If the number of > > > > streams really are important I would do a 1/n thing on the line below. > > > > If the line is keept I would also print the cookie. > > > > > > I'm sorry I didn't fully get this one. What do you mean with "a 1/n > > > thing on the line below" ? > > > > > > Also, I think identifying how many streams the request contains is > > > relevant. > > > > I was thinking of if it make sens to instead of > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > Have something like, > > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > I find the later more compact while at the same time providing more > > information in a situation where you have to debug from a log file. > > So, that might be a matter of tastes, but: > 1) I try to avoid creating too long log lines > I always run with terminals one side to the other, spanning more > than the usual 80-cols is ok, as it's reasonable to suppose most > people have larger screens nowadays, but I think we should try to > be compact to ease debug/development > > 2) I try to separate information in lines, as log can be filtered, > either by using libcamera log infrastructure or by piping the usual > unix tools. In your example, reporting the same cookie in two lines > to me add noise and makes debug more confusing than having > information separated on multiple lines. I can easily filter/grep > on lines I'm interested in, and I prefer one more line to parse > than parsing information on a single long line > > Might be a matter of tastes indeed I agree, it's a matter of taste. > > > > > > > > > > > > > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > > > > > I would add the cookie. > > > > > > > > > ... > > > > > ... > > > > > Request request.cpp:268 Request has completed - cookie: 138508601718368 > > > > > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams > > > > > > > > I would add the cookie and possibly s/with 1 streams// > > > > > > If we remove the stream count and add the cookie, I would then rather > > > drop the printout in camera_device.cpp completely, as it will provide > > > the exact same information that the one in request.cpp provides... > > > > Is it a problem that the same information is printed at different > > levels? I like to see such things as it allows me to from a log file > > track how a request moved thru the layers. Also if I'm only interested > > in debugging a specific component maybe I have a > > LIBCAMERA_LOG_LEVELS=HAL:0 or such set? > > Ok addin the cookie to the request complete log > > > > > In either case as stated in my first reply this is all bikeshedding so I > > don't feel strongly about any of it :-) > > > > > > > > > > > > > Bikeshedding is fun but take only what you like. At the end if all lines > > > > have the cookie you can also take my, > > > > > > > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > > Thanks, I'll send a new version and I'll retain the tag, but please > feel free to comment on that one as well. Please retain the tag, I'm just bikeshedding. > > Thanks > j > > > > > > > > > > > > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> > > > > > --- > > > > > src/android/camera_device.cpp | 3 +++ > > > > > src/libcamera/request.cpp | 2 ++ > > > > > 2 files changed, 5 insertions(+) > > > > > > > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > > > > > index a9634f4e4198..513f000b1854 100644 > > > > > --- a/src/android/camera_device.cpp > > > > > +++ b/src/android/camera_device.cpp > > > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > > > > > status = CAMERA3_BUFFER_STATUS_ERROR; > > > > > } > > > > > > > > > > + LOG(HAL, Debug) << "Request completed by libcamera with " > > > > > + << descriptor->numBuffers_ << " streams"; > > > > > + > > > > > /* > > > > > * \todo The timestamp used for the metadata is currently always taken > > > > > * from the first buffer (which may be the first stream) in the Request. > > > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > > > > > index a68684ef9fd3..e561ce1d5d0e 100644 > > > > > --- a/src/libcamera/request.cpp > > > > > +++ b/src/libcamera/request.cpp > > > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > > > > > metadata_ = new ControlList(controls::controls); > > > > > > > > > > LIBCAMERA_TRACEPOINT(request_construct, this); > > > > > + > > > > > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > > > > > } > > > > > > > > > > Request::~Request() > > > > > -- > > > > > 2.30.0 > > > > > > > > > > _______________________________________________ > > > > > libcamera-devel mailing list > > > > > libcamera-devel@lists.libcamera.org > > > > > https://lists.libcamera.org/listinfo/libcamera-devel > > > > > > > > -- > > > > Regards, > > > > Niklas Söderlund > > > > -- > > Regards, > > Niklas Söderlund
Hi Jacopo, Thank you for the patch. On Tue, Feb 02, 2021 at 12:40:56PM +0100, Jacopo Mondi wrote: > On Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote: > > On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote: > > > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote: > > > > Hi Jacopo, > > > > > > > > Thanks for your bikeshedding opportunity :-) > > > > > > > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote: > > > > > The current logging to track the status of a Request when running the > > > > > Android camera HAL provide the following information: > > > > > > > > > > When a Request is queued to libcamera: > > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > > > > > When a Request completes: > > > > > Request request.cpp:268 Request has completed - cookie: 138508601719648 > > > > > > > > > > The queueing of a Request reports the number of streams it contains > > > > > while the completion of a Request reports the address of the associated > > > > > cookie. > > > > > > > > > > This makes very hard to keep track of what Requests have completed, as > > > > > the logging associated with a queue/complete event does not allow to identify > > > > > a Request easily. > > > > > > > > > > Add two more printouts to make it easier to track a Request life cycle. > > > > > > > > > > The result looks like the following trace: > > > > > > > > > > > > > I like the improvement, but I would alter it slightly. I think having > > > > the cookie value is the real value here as it makes it possible to trace > > > > a request. > > > > > > > > > Request request.cpp:92 Created request - cookie: 138508601718368 > > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams > > > > > > > > I would remove this print to increase signal to noise. If the number of > > > > streams really are important I would do a 1/n thing on the line below. > > > > If the line is keept I would also print the cookie. > > > > > > I'm sorry I didn't fully get this one. What do you mean with "a 1/n > > > thing on the line below" ? > > > > > > Also, I think identifying how many streams the request contains is > > > relevant. > > > > I was thinking of if it make sens to instead of > > > > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > Have something like, > > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > I find the later more compact while at the same time providing more > > information in a situation where you have to debug from a log file. > > So, that might be a matter of tastes, but: > 1) I try to avoid creating too long log lines > I always run with terminals one side to the other, spanning more > than the usual 80-cols is ok, as it's reasonable to suppose most > people have larger screens nowadays, but I think we should try to > be compact to ease debug/development > > 2) I try to separate information in lines, as log can be filtered, > either by using libcamera log infrastructure or by piping the usual > unix tools. In your example, reporting the same cookie in two lines > to me add noise and makes debug more confusing than having > information separated on multiple lines. I can easily filter/grep > on lines I'm interested in, and I prefer one more line to parse > than parsing information on a single long line > > Might be a matter of tastes indeed I know this has been merged already, and there's no need to change anything now, but I wanted to point out that the tracing infrastructure is a good candidate to trace requests. > > > > > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) > > > > > > > > I would add the cookie. > > > > > > > > > ... > > > > > ... > > > > > Request request.cpp:268 Request has completed - cookie: 138508601718368 > > > > > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams > > > > > > > > I would add the cookie and possibly s/with 1 streams// > > > > > > If we remove the stream count and add the cookie, I would then rather > > > drop the printout in camera_device.cpp completely, as it will provide > > > the exact same information that the one in request.cpp provides... > > > > Is it a problem that the same information is printed at different > > levels? I like to see such things as it allows me to from a log file > > track how a request moved thru the layers. Also if I'm only interested > > in debugging a specific component maybe I have a > > LIBCAMERA_LOG_LEVELS=HAL:0 or such set? > > Ok addin the cookie to the request complete log > > > In either case as stated in my first reply this is all bikeshedding so I > > don't feel strongly about any of it :-) > > > > > > Bikeshedding is fun but take only what you like. At the end if all lines > > > > have the cookie you can also take my, > > > > > > > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > > Thanks, I'll send a new version and I'll retain the tag, but please > feel free to comment on that one as well. > > > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> > > > > > --- > > > > > src/android/camera_device.cpp | 3 +++ > > > > > src/libcamera/request.cpp | 2 ++ > > > > > 2 files changed, 5 insertions(+) > > > > > > > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp > > > > > index a9634f4e4198..513f000b1854 100644 > > > > > --- a/src/android/camera_device.cpp > > > > > +++ b/src/android/camera_device.cpp > > > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) > > > > > status = CAMERA3_BUFFER_STATUS_ERROR; > > > > > } > > > > > > > > > > + LOG(HAL, Debug) << "Request completed by libcamera with " > > > > > + << descriptor->numBuffers_ << " streams"; > > > > > + > > > > > /* > > > > > * \todo The timestamp used for the metadata is currently always taken > > > > > * from the first buffer (which may be the first stream) in the Request. > > > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp > > > > > index a68684ef9fd3..e561ce1d5d0e 100644 > > > > > --- a/src/libcamera/request.cpp > > > > > +++ b/src/libcamera/request.cpp > > > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) > > > > > metadata_ = new ControlList(controls::controls); > > > > > > > > > > LIBCAMERA_TRACEPOINT(request_construct, this); > > > > > + > > > > > + LOG(Request, Debug) << "Created request - cookie: " << cookie_; > > > > > } > > > > > > > > > > Request::~Request()
diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp index a9634f4e4198..513f000b1854 100644 --- a/src/android/camera_device.cpp +++ b/src/android/camera_device.cpp @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request) status = CAMERA3_BUFFER_STATUS_ERROR; } + LOG(HAL, Debug) << "Request completed by libcamera with " + << descriptor->numBuffers_ << " streams"; + /* * \todo The timestamp used for the metadata is currently always taken * from the first buffer (which may be the first stream) in the Request. diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp index a68684ef9fd3..e561ce1d5d0e 100644 --- a/src/libcamera/request.cpp +++ b/src/libcamera/request.cpp @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie) metadata_ = new ControlList(controls::controls); LIBCAMERA_TRACEPOINT(request_construct, this); + + LOG(Request, Debug) << "Created request - cookie: " << cookie_; } Request::~Request()
The current logging to track the status of a Request when running the Android camera HAL provide the following information: When a Request is queued to libcamera: HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams When a Request completes: Request request.cpp:268 Request has completed - cookie: 138508601719648 The queueing of a Request reports the number of streams it contains while the completion of a Request reports the address of the associated cookie. This makes very hard to keep track of what Requests have completed, as the logging associated with a queue/complete event does not allow to identify a Request easily. Add two more printouts to make it easier to track a Request life cycle. The result looks like the following trace: Request request.cpp:92 Created request - cookie: 138508601718368 HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct) ... ... Request request.cpp:268 Request has completed - cookie: 138508601718368 HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams Signed-off-by: Jacopo Mondi <jacopo@jmondi.org> --- src/android/camera_device.cpp | 3 +++ src/libcamera/request.cpp | 2 ++ 2 files changed, 5 insertions(+)