[{"id":14862,"web_url":"https://patchwork.libcamera.org/comment/14862/","msgid":"<YBSZr4BQrHLbrURd@oden.dyn.berto.se>","date":"2021-01-29T23:26:39","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":5,"url":"https://patchwork.libcamera.org/api/people/5/","name":"Niklas Söderlund","email":"niklas.soderlund@ragnatech.se"},"content":"Hi Jacopo,\n\nThanks for your bikeshedding opportunity :-)\n\nOn 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:\n> The current logging to track the status of a Request when running the\n> Android camera HAL provide the following information:\n> \n> When a Request is queued to libcamera:\n> HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> \n> When a Request completes:\n> Request request.cpp:268 Request has completed - cookie: 138508601719648\n> \n> The queueing of a Request reports the number of streams it contains\n> while the completion of a Request reports the address of the associated\n> cookie.\n> \n> This makes very hard to keep track of what Requests have completed, as\n> the logging associated with a queue/complete event does not allow to identify\n> a Request easily.\n> \n> Add two more printouts to make it easier to track a Request life cycle.\n> \n> The result looks like the following trace:\n> \n\nI like the improvement, but I would alter it slightly. I think having \nthe cookie value is the real value here as it makes it possible to trace \na request.\n\n> Request request.cpp:92 Created request - cookie: 138508601718368\n> HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n\nI would remove this print to increase signal to noise. If the number of \nstreams really are important I would do a 1/n thing on the line below.  \nIf the line is keept I would also print the cookie.\n\n> HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n\nI would add the cookie.\n\n> ...\n> ...\n> Request request.cpp:268 Request has completed - cookie: 138508601718368\n> HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n\nI would add the cookie and possibly s/with 1 streams//\n\nBikeshedding is fun but take only what you like. At the end if all lines \nhave the cookie you can also take my,\n\nReviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se>\n\n> \n> Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n> ---\n>  src/android/camera_device.cpp | 3 +++\n>  src/libcamera/request.cpp     | 2 ++\n>  2 files changed, 5 insertions(+)\n> \n> diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> index a9634f4e4198..513f000b1854 100644\n> --- a/src/android/camera_device.cpp\n> +++ b/src/android/camera_device.cpp\n> @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n>  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n>  \t}\n>  \n> +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> +\n>  \t/*\n>  \t * \\todo The timestamp used for the metadata is currently always taken\n>  \t * from the first buffer (which may be the first stream) in the Request.\n> diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> index a68684ef9fd3..e561ce1d5d0e 100644\n> --- a/src/libcamera/request.cpp\n> +++ b/src/libcamera/request.cpp\n> @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n>  \tmetadata_ = new ControlList(controls::controls);\n>  \n>  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> +\n> +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n>  }\n>  \n>  Request::~Request()\n> -- \n> 2.30.0\n> \n> _______________________________________________\n> libcamera-devel mailing list\n> libcamera-devel@lists.libcamera.org\n> https://lists.libcamera.org/listinfo/libcamera-devel","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id D492CC33BB\n\tfor <parsemail@patchwork.libcamera.org>;\n\tFri, 29 Jan 2021 23:26:42 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 6125C683BE;\n\tSat, 30 Jan 2021 00:26:42 +0100 (CET)","from mail-lj1-x22e.google.com (mail-lj1-x22e.google.com\n\t[IPv6:2a00:1450:4864:20::22e])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id F17E96030A\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tSat, 30 Jan 2021 00:26:40 +0100 (CET)","by mail-lj1-x22e.google.com with SMTP id r14so12421059ljc.2\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tFri, 29 Jan 2021 15:26:40 -0800 (PST)","from localhost (h-209-203.A463.priv.bahnhof.se. [155.4.209.203])\n\tby smtp.gmail.com with ESMTPSA id\n\tc7sm2684270ljd.95.2021.01.29.15.26.39\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tFri, 29 Jan 2021 15:26:39 -0800 (PST)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=ragnatech-se.20150623.gappssmtp.com\n\theader.i=@ragnatech-se.20150623.gappssmtp.com\n\theader.b=\"JFvd9PKL\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=ragnatech-se.20150623.gappssmtp.com; s=20150623;\n\th=date:from:to:cc:subject:message-id:references:mime-version\n\t:content-disposition:content-transfer-encoding:in-reply-to;\n\tbh=8yRn47VWPUBaSml3/VEAJXzHd9ny7LgNeOWVGGQuMvY=;\n\tb=JFvd9PKLAre5Aan09UjMvR2tHvvJjVegjRmyeOhfRQA9gJNTVFHz21xSKR6+dFKCtT\n\tBOxduoAMHZ7N13fFPiiNobzrobwni2jvkLBkTNm8L5xo9u3INa0Pr8FWeaXpMxHJWV/+\n\tjXlBgmKoZ4xmftqrMLzs6Q/pmrarbTTFPr8gfloTh1V83xFmNwgzEIBHZqZjTABFh7Jq\n\to5bxV15oSdXuuvVgMgrMGY2ep03Kpo398fCdZD0IEmwRBTVaStEFMPk/oZn1/uqPZTub\n\tA9OAU7xFVIlp5hFLmhtrSN1F0tC/VNh9k4yuc7GeVI7T7NuQt/1TPyVa02W2iW4dKkK4\n\tqLHA==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:date:from:to:cc:subject:message-id:references\n\t:mime-version:content-disposition:content-transfer-encoding\n\t:in-reply-to;\n\tbh=8yRn47VWPUBaSml3/VEAJXzHd9ny7LgNeOWVGGQuMvY=;\n\tb=XI3pv4PsUFEe6uXVfOH00/7yqt5SZjjFJQFkIGFpJ+oJD+Ai3HvnHUsb/UGSHdvzlf\n\t88rhrzsMWt5ulHK9+WiCmo8Dz5oo9GdYRRP8hkL0Q4LxI/2nERPrJSmnekTVu7fkshG3\n\t5Q2Uwupm6/K6ClVP43pfr5nnxT3LwMd0hrAupM8iaKxucFr6AIj9d9B4gHfpQJlaZT/u\n\tprtae4mBvdfPGbP1C2MJqSP2AtgjNicKTiVM0kKdms7chwXMbeSVtgkWv1cNjritPF7j\n\tCtVDnBVqyCU3aLFejnpl+zIe//5LxJm9oWOOf+FVBqIX41hU51mRrfQ1ALfRj/zDCKKf\n\t0YcQ==","X-Gm-Message-State":"AOAM5301if7a1mjtaPe2cor/oTCGsuDBrTQTjzJMuYwBkGaPDE9LKV3V\n\tGk/rab80RWGRTIjdAnyuztOFdA==","X-Google-Smtp-Source":"ABdhPJwOvuuMxLDCtqWR7osXDIwndUHpLlQFtGJuVWp71sBzyLNYbVDUIzyGy16I83cYfB+Z+Hii0g==","X-Received":"by 2002:a2e:9051:: with SMTP id\n\tn17mr3787960ljg.172.1611962800363; \n\tFri, 29 Jan 2021 15:26:40 -0800 (PST)","Date":"Sat, 30 Jan 2021 00:26:39 +0100","From":"Niklas =?iso-8859-1?q?S=F6derlund?= <niklas.soderlund@ragnatech.se>","To":"Jacopo Mondi <jacopo@jmondi.org>","Message-ID":"<YBSZr4BQrHLbrURd@oden.dyn.berto.se>","References":"<20210128090454.515268-1-jacopo@jmondi.org>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210128090454.515268-1-jacopo@jmondi.org>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"iso-8859-1\"","Content-Transfer-Encoding":"quoted-printable","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}},{"id":14876,"web_url":"https://patchwork.libcamera.org/comment/14876/","msgid":"<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>","date":"2021-02-01T10:36:48","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":3,"url":"https://patchwork.libcamera.org/api/people/3/","name":"Jacopo Mondi","email":"jacopo@jmondi.org"},"content":"Hi Niklas,\n\nOn Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote:\n> Hi Jacopo,\n>\n> Thanks for your bikeshedding opportunity :-)\n>\n> On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:\n> > The current logging to track the status of a Request when running the\n> > Android camera HAL provide the following information:\n> >\n> > When a Request is queued to libcamera:\n> > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> >\n> > When a Request completes:\n> > Request request.cpp:268 Request has completed - cookie: 138508601719648\n> >\n> > The queueing of a Request reports the number of streams it contains\n> > while the completion of a Request reports the address of the associated\n> > cookie.\n> >\n> > This makes very hard to keep track of what Requests have completed, as\n> > the logging associated with a queue/complete event does not allow to identify\n> > a Request easily.\n> >\n> > Add two more printouts to make it easier to track a Request life cycle.\n> >\n> > The result looks like the following trace:\n> >\n>\n> I like the improvement, but I would alter it slightly. I think having\n> the cookie value is the real value here as it makes it possible to trace\n> a request.\n>\n> > Request request.cpp:92 Created request - cookie: 138508601718368\n> > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n>\n> I would remove this print to increase signal to noise. If the number of\n> streams really are important I would do a 1/n thing on the line below.\n> If the line is keept I would also print the cookie.\n\nI'm sorry I didn't fully get this one. What do you mean with \"a 1/n\nthing on the line below\" ?\n\nAlso, I think identifying how many streams the request contains is\nrelevant.\n\n>\n> > HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n>\n> I would add the cookie.\n>\n> > ...\n> > ...\n> > Request request.cpp:268 Request has completed - cookie: 138508601718368\n> > HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n>\n> I would add the cookie and possibly s/with 1 streams//\n\nIf we remove the stream count and add the cookie, I would then rather\ndrop the printout in camera_device.cpp completely, as it will provide\nthe exact same information that the one in request.cpp provides...\n\n>\n> Bikeshedding is fun but take only what you like. At the end if all lines\n> have the cookie you can also take my,\n>\n> Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se>\n>\n> >\n> > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n> > ---\n> >  src/android/camera_device.cpp | 3 +++\n> >  src/libcamera/request.cpp     | 2 ++\n> >  2 files changed, 5 insertions(+)\n> >\n> > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> > index a9634f4e4198..513f000b1854 100644\n> > --- a/src/android/camera_device.cpp\n> > +++ b/src/android/camera_device.cpp\n> > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n> >  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n> >  \t}\n> >\n> > +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> > +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> > +\n> >  \t/*\n> >  \t * \\todo The timestamp used for the metadata is currently always taken\n> >  \t * from the first buffer (which may be the first stream) in the Request.\n> > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> > index a68684ef9fd3..e561ce1d5d0e 100644\n> > --- a/src/libcamera/request.cpp\n> > +++ b/src/libcamera/request.cpp\n> > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n> >  \tmetadata_ = new ControlList(controls::controls);\n> >\n> >  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> > +\n> > +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n> >  }\n> >\n> >  Request::~Request()\n> > --\n> > 2.30.0\n> >\n> > _______________________________________________\n> > libcamera-devel mailing list\n> > libcamera-devel@lists.libcamera.org\n> > https://lists.libcamera.org/listinfo/libcamera-devel\n>\n> --\n> Regards,\n> Niklas Söderlund","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id ADD7AC33BB\n\tfor <parsemail@patchwork.libcamera.org>;\n\tMon,  1 Feb 2021 10:36:29 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 44D7B683FD;\n\tMon,  1 Feb 2021 11:36:29 +0100 (CET)","from relay12.mail.gandi.net (relay12.mail.gandi.net\n\t[217.70.178.232])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 6EE1F60307\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tMon,  1 Feb 2021 11:36:27 +0100 (CET)","from uno.localdomain (93-61-96-190.ip145.fastwebnet.it\n\t[93.61.96.190]) (Authenticated sender: jacopo@jmondi.org)\n\tby relay12.mail.gandi.net (Postfix) with ESMTPSA id CF82020000D;\n\tMon,  1 Feb 2021 10:36:26 +0000 (UTC)"],"Date":"Mon, 1 Feb 2021 11:36:48 +0100","From":"Jacopo Mondi <jacopo@jmondi.org>","To":"Niklas =?utf-8?q?S=C3=B6derlund?= <niklas.soderlund@ragnatech.se>","Message-ID":"<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>","References":"<20210128090454.515268-1-jacopo@jmondi.org>\n\t<YBSZr4BQrHLbrURd@oden.dyn.berto.se>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<YBSZr4BQrHLbrURd@oden.dyn.berto.se>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"utf-8\"","Content-Transfer-Encoding":"base64","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}},{"id":14883,"web_url":"https://patchwork.libcamera.org/comment/14883/","msgid":"<YBgndGBY64hO6D6e@oden.dyn.berto.se>","date":"2021-02-01T16:08:20","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":5,"url":"https://patchwork.libcamera.org/api/people/5/","name":"Niklas Söderlund","email":"niklas.soderlund@ragnatech.se"},"content":"Hi Jacopo,\n\nOn 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote:\n> Hi Niklas,\n> \n> On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote:\n> > Hi Jacopo,\n> >\n> > Thanks for your bikeshedding opportunity :-)\n> >\n> > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:\n> > > The current logging to track the status of a Request when running the\n> > > Android camera HAL provide the following information:\n> > >\n> > > When a Request is queued to libcamera:\n> > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > >\n> > > When a Request completes:\n> > > Request request.cpp:268 Request has completed - cookie: 138508601719648\n> > >\n> > > The queueing of a Request reports the number of streams it contains\n> > > while the completion of a Request reports the address of the associated\n> > > cookie.\n> > >\n> > > This makes very hard to keep track of what Requests have completed, as\n> > > the logging associated with a queue/complete event does not allow to identify\n> > > a Request easily.\n> > >\n> > > Add two more printouts to make it easier to track a Request life cycle.\n> > >\n> > > The result looks like the following trace:\n> > >\n> >\n> > I like the improvement, but I would alter it slightly. I think having\n> > the cookie value is the real value here as it makes it possible to trace\n> > a request.\n> >\n> > > Request request.cpp:92 Created request - cookie: 138508601718368\n> > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> >\n> > I would remove this print to increase signal to noise. If the number of\n> > streams really are important I would do a 1/n thing on the line below.\n> > If the line is keept I would also print the cookie.\n> \n> I'm sorry I didn't fully get this one. What do you mean with \"a 1/n\n> thing on the line below\" ?\n> \n> Also, I think identifying how many streams the request contains is\n> relevant.\n\nI was thinking of if it make sens to instead of\n\n  HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams\n  HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n  HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n\nHave something like,\n\n  HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n  HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n\nI find the later more compact while at the same time providing more \ninformation in a situation where you have to debug from a log file.\n\n> \n> >\n> > > HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >\n> > I would add the cookie.\n> >\n> > > ...\n> > > ...\n> > > Request request.cpp:268 Request has completed - cookie: 138508601718368\n> > > HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n> >\n> > I would add the cookie and possibly s/with 1 streams//\n> \n> If we remove the stream count and add the cookie, I would then rather\n> drop the printout in camera_device.cpp completely, as it will provide\n> the exact same information that the one in request.cpp provides...\n\nIs it a problem that the same information is printed at different \nlevels? I like to see such things as it allows me to from a log file \ntrack how a request moved thru the layers. Also if I'm only interested \nin debugging a specific component maybe I have a \nLIBCAMERA_LOG_LEVELS=HAL:0 or such set?\n\nIn either case as stated in my first reply this is all bikeshedding so I \ndon't feel strongly about any of it :-)\n\n> \n> >\n> > Bikeshedding is fun but take only what you like. At the end if all lines\n> > have the cookie you can also take my,\n> >\n> > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se>\n> >\n> > >\n> > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n> > > ---\n> > >  src/android/camera_device.cpp | 3 +++\n> > >  src/libcamera/request.cpp     | 2 ++\n> > >  2 files changed, 5 insertions(+)\n> > >\n> > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> > > index a9634f4e4198..513f000b1854 100644\n> > > --- a/src/android/camera_device.cpp\n> > > +++ b/src/android/camera_device.cpp\n> > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n> > >  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n> > >  \t}\n> > >\n> > > +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> > > +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> > > +\n> > >  \t/*\n> > >  \t * \\todo The timestamp used for the metadata is currently always taken\n> > >  \t * from the first buffer (which may be the first stream) in the Request.\n> > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> > > index a68684ef9fd3..e561ce1d5d0e 100644\n> > > --- a/src/libcamera/request.cpp\n> > > +++ b/src/libcamera/request.cpp\n> > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n> > >  \tmetadata_ = new ControlList(controls::controls);\n> > >\n> > >  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> > > +\n> > > +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n> > >  }\n> > >\n> > >  Request::~Request()\n> > > --\n> > > 2.30.0\n> > >\n> > > _______________________________________________\n> > > libcamera-devel mailing list\n> > > libcamera-devel@lists.libcamera.org\n> > > https://lists.libcamera.org/listinfo/libcamera-devel\n> >\n> > --\n> > Regards,\n> > Niklas Söderlund","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 0D83ABD808\n\tfor <parsemail@patchwork.libcamera.org>;\n\tMon,  1 Feb 2021 16:08:26 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 943C9683FF;\n\tMon,  1 Feb 2021 17:08:25 +0100 (CET)","from mail-lj1-x233.google.com (mail-lj1-x233.google.com\n\t[IPv6:2a00:1450:4864:20::233])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 60D83683FF\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tMon,  1 Feb 2021 17:08:23 +0100 (CET)","by mail-lj1-x233.google.com with SMTP id m22so12837001ljj.4\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tMon, 01 Feb 2021 08:08:23 -0800 (PST)","from localhost (h-209-203.A463.priv.bahnhof.se. [155.4.209.203])\n\tby smtp.gmail.com with ESMTPSA id\n\tq3sm3845236ljp.108.2021.02.01.08.08.21\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tMon, 01 Feb 2021 08:08:21 -0800 (PST)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=ragnatech-se.20150623.gappssmtp.com\n\theader.i=@ragnatech-se.20150623.gappssmtp.com\n\theader.b=\"mylJVgPD\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=ragnatech-se.20150623.gappssmtp.com; s=20150623;\n\th=date:from:to:cc:subject:message-id:references:mime-version\n\t:content-disposition:content-transfer-encoding:in-reply-to;\n\tbh=t3ctVvXyNYSM1qF3QS07hxD+d27wmXvSB9crc41ndfY=;\n\tb=mylJVgPDHHEjbEHqw4bwIGa9JDjqd60HprkuMrYqSNWR6UNKPYY6ymrwHzBwRNl98K\n\tYWWybb2L99D+icLdrGAqiv0ifoyMvPzNL2rWB/m3Q3YfpAynZ2LGGqsiA1F6RGABQ4aA\n\toEF3RrnPlaHHer9r/AnQfVMmpSLOlkUif1pCVkeV0gZs+Zf1KUZJUpl7lDqevQVVzITo\n\tB4cVyEcm9ukKxDXac6c0yIUlmd6ZjGxCMB0yuJ7NNNbmsFP9Jov4g9703LM4x9DJaZG3\n\tHOCphAwrk8Oe3jObiRjQCjaxyD/5zbKUoJ7WPA/IlpqZ5mtX7ftQn4ckG7AM6ICGhLk1\n\tOp6w==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:date:from:to:cc:subject:message-id:references\n\t:mime-version:content-disposition:content-transfer-encoding\n\t:in-reply-to;\n\tbh=t3ctVvXyNYSM1qF3QS07hxD+d27wmXvSB9crc41ndfY=;\n\tb=qf1jrAu02UyQjEUpExO4oAWX5Rj/PsqUP772m/xUpfF2/Cgj18bgGhx1CpuH/h8or2\n\t97no4ehy0o1zKpbymhgX7vqfoZPAgxJ/FtCjXU9NFic+4cyizP2B3f9UCvJzbBvyI/f7\n\t6EV0FxGYBJOgnHOgFXbyDepUH8nsLeW8KLjrtTYaOP4UD8g9G6TNIg4MJUISGc+Ftgrj\n\tQEd8qC0hoWl7e55RPJCkN938LTu9DWGzyPQhTpLjuf77BiBqf4I8/ACcOwvGfV/vQGNc\n\tEOk61OulV1yuU7CS5EPhyGvVcLWJ774NpMPxvlSWJUEWt6sRP6Uo1WJs32Z92Q5Of5w0\n\tyyyw==","X-Gm-Message-State":"AOAM533MsXsCYh7r8wz7NXV5p0xaQQ2HQExTTpnoigweLPQ6AdoCPZT0\n\trvMBGxlcv03+hmgKCB0hZBhNJyTAzXQyFQ==","X-Google-Smtp-Source":"ABdhPJxY6d8ObhraTiNBJDeLks0Q3VLmqheqPo4+t1GknGqyeyBFaxtrx78Wr63Zx1RVFR8s84bTkg==","X-Received":"by 2002:a2e:80d2:: with SMTP id\n\tr18mr10356421ljg.453.1612195702678; \n\tMon, 01 Feb 2021 08:08:22 -0800 (PST)","Date":"Mon, 1 Feb 2021 17:08:20 +0100","From":"Niklas =?iso-8859-1?q?S=F6derlund?= <niklas.soderlund@ragnatech.se>","To":"Jacopo Mondi <jacopo@jmondi.org>","Message-ID":"<YBgndGBY64hO6D6e@oden.dyn.berto.se>","References":"<20210128090454.515268-1-jacopo@jmondi.org>\n\t<YBSZr4BQrHLbrURd@oden.dyn.berto.se>\n\t<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"iso-8859-1\"","Content-Transfer-Encoding":"quoted-printable","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}},{"id":14899,"web_url":"https://patchwork.libcamera.org/comment/14899/","msgid":"<20210202025327.GA42962@pyrite.rasen.tech>","date":"2021-02-02T02:53:27","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":17,"url":"https://patchwork.libcamera.org/api/people/17/","name":"Paul Elder","email":"paul.elder@ideasonboard.com"},"content":"Hi Jacopo,\n\nOn Thu, Jan 28, 2021 at 10:04:54AM +0100, Jacopo Mondi wrote:\n> The current logging to track the status of a Request when running the\n> Android camera HAL provide the following information:\n> \n> When a Request is queued to libcamera:\n> HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> \n> When a Request completes:\n> Request request.cpp:268 Request has completed - cookie: 138508601719648\n> \n> The queueing of a Request reports the number of streams it contains\n> while the completion of a Request reports the address of the associated\n> cookie.\n> \n> This makes very hard to keep track of what Requests have completed, as\n> the logging associated with a queue/complete event does not allow to identify\n> a Request easily.\n> \n> Add two more printouts to make it easier to track a Request life cycle.\n> \n> The result looks like the following trace:\n> \n> Request request.cpp:92 Created request - cookie: 138508601718368\n> HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> ...\n> ...\n> Request request.cpp:268 Request has completed - cookie: 138508601718368\n> HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n> \n> Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n\nOoh, good idea!\n\nReviewed-by: Paul Elder <paul.elder@ideasonboard.com>\n\n> ---\n>  src/android/camera_device.cpp | 3 +++\n>  src/libcamera/request.cpp     | 2 ++\n>  2 files changed, 5 insertions(+)\n> \n> diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> index a9634f4e4198..513f000b1854 100644\n> --- a/src/android/camera_device.cpp\n> +++ b/src/android/camera_device.cpp\n> @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n>  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n>  \t}\n>  \n> +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> +\n>  \t/*\n>  \t * \\todo The timestamp used for the metadata is currently always taken\n>  \t * from the first buffer (which may be the first stream) in the Request.\n> diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> index a68684ef9fd3..e561ce1d5d0e 100644\n> --- a/src/libcamera/request.cpp\n> +++ b/src/libcamera/request.cpp\n> @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n>  \tmetadata_ = new ControlList(controls::controls);\n>  \n>  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> +\n> +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n>  }\n>  \n>  Request::~Request()\n> -- \n> 2.30.0\n> \n> _______________________________________________\n> libcamera-devel mailing list\n> libcamera-devel@lists.libcamera.org\n> https://lists.libcamera.org/listinfo/libcamera-devel","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 77C5CBD808\n\tfor <parsemail@patchwork.libcamera.org>;\n\tTue,  2 Feb 2021 02:53:38 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 11DCA60106;\n\tTue,  2 Feb 2021 03:53:38 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[213.167.242.64])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 5888660106\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tTue,  2 Feb 2021 03:53:36 +0100 (CET)","from pyrite.rasen.tech (unknown\n\t[IPv6:2400:4051:61:600:2c71:1b79:d06d:5032])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id BC526556;\n\tTue,  2 Feb 2021 03:53:34 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"MZyVXSjB\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1612234415;\n\tbh=/Z9EnZ+25v49WaYyjGqhJ1He0dcrlvYiE+L45/Gezt4=;\n\th=Date:From:To:Cc:Subject:References:In-Reply-To:From;\n\tb=MZyVXSjBB13tDMEstfNh/utXXlg/UxYl6anqZuzmaGs3RsWOaoMGlAzpjShhIgPZx\n\t/cii+VCZSlkII8KnLvrp3hGalrZLvoR4eiVhAcfbPpY5fCcvHMFCg6QM8+gg1hjjBH\n\tu01juxlqLYDgJD+6aRNaKLEpZszRnui7hUgzXJHk=","Date":"Tue, 2 Feb 2021 11:53:27 +0900","From":"paul.elder@ideasonboard.com","To":"Jacopo Mondi <jacopo@jmondi.org>","Message-ID":"<20210202025327.GA42962@pyrite.rasen.tech>","References":"<20210128090454.515268-1-jacopo@jmondi.org>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210128090454.515268-1-jacopo@jmondi.org>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}},{"id":14903,"web_url":"https://patchwork.libcamera.org/comment/14903/","msgid":"<20210202114056.wravl5wx6mtog77k@uno.localdomain>","date":"2021-02-02T11:40:56","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":3,"url":"https://patchwork.libcamera.org/api/people/3/","name":"Jacopo Mondi","email":"jacopo@jmondi.org"},"content":"Hi Niklas,\n\nOn Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote:\n> Hi Jacopo,\n>\n> On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote:\n> > Hi Niklas,\n> >\n> > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote:\n> > > Hi Jacopo,\n> > >\n> > > Thanks for your bikeshedding opportunity :-)\n> > >\n> > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:\n> > > > The current logging to track the status of a Request when running the\n> > > > Android camera HAL provide the following information:\n> > > >\n> > > > When a Request is queued to libcamera:\n> > > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > > >\n> > > > When a Request completes:\n> > > > Request request.cpp:268 Request has completed - cookie: 138508601719648\n> > > >\n> > > > The queueing of a Request reports the number of streams it contains\n> > > > while the completion of a Request reports the address of the associated\n> > > > cookie.\n> > > >\n> > > > This makes very hard to keep track of what Requests have completed, as\n> > > > the logging associated with a queue/complete event does not allow to identify\n> > > > a Request easily.\n> > > >\n> > > > Add two more printouts to make it easier to track a Request life cycle.\n> > > >\n> > > > The result looks like the following trace:\n> > > >\n> > >\n> > > I like the improvement, but I would alter it slightly. I think having\n> > > the cookie value is the real value here as it makes it possible to trace\n> > > a request.\n> > >\n> > > > Request request.cpp:92 Created request - cookie: 138508601718368\n> > > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > >\n> > > I would remove this print to increase signal to noise. If the number of\n> > > streams really are important I would do a 1/n thing on the line below.\n> > > If the line is keept I would also print the cookie.\n> >\n> > I'm sorry I didn't fully get this one. What do you mean with \"a 1/n\n> > thing on the line below\" ?\n> >\n> > Also, I think identifying how many streams the request contains is\n> > relevant.\n>\n> I was thinking of if it make sens to instead of\n>\n>   HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams\n>   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n>   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n>\n> Have something like,\n>\n>   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n>   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n>\n> I find the later more compact while at the same time providing more\n> information in a situation where you have to debug from a log file.\n\nSo, that might be a matter of tastes, but:\n1) I try to avoid creating too long log lines\n   I always run with terminals one side to the other, spanning more\n   than the usual 80-cols is ok, as it's reasonable to suppose most\n   people have larger screens nowadays, but I think we should try to\n   be compact to ease debug/development\n\n2) I try to separate information in lines, as log can be filtered,\n   either by using libcamera log infrastructure or by piping the usual\n   unix tools. In your example, reporting the same cookie in two lines\n   to me add noise and makes debug more confusing than having\n   information separated on multiple lines. I can easily filter/grep\n   on lines I'm interested in, and I prefer one more line to parse\n   than parsing information on a single long line\n\nMight be a matter of tastes indeed\n\n>\n> >\n> > >\n> > > > HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> > >\n> > > I would add the cookie.\n> > >\n> > > > ...\n> > > > ...\n> > > > Request request.cpp:268 Request has completed - cookie: 138508601718368\n> > > > HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n> > >\n> > > I would add the cookie and possibly s/with 1 streams//\n> >\n> > If we remove the stream count and add the cookie, I would then rather\n> > drop the printout in camera_device.cpp completely, as it will provide\n> > the exact same information that the one in request.cpp provides...\n>\n> Is it a problem that the same information is printed at different\n> levels? I like to see such things as it allows me to from a log file\n> track how a request moved thru the layers. Also if I'm only interested\n> in debugging a specific component maybe I have a\n> LIBCAMERA_LOG_LEVELS=HAL:0 or such set?\n\nOk addin the cookie to the request complete log\n\n>\n> In either case as stated in my first reply this is all bikeshedding so I\n> don't feel strongly about any of it :-)\n>\n> >\n> > >\n> > > Bikeshedding is fun but take only what you like. At the end if all lines\n> > > have the cookie you can also take my,\n> > >\n> > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se>\n\nThanks, I'll send a new version and I'll retain the tag, but please\nfeel free to comment on that one as well.\n\nThanks\n  j\n\n> > >\n> > > >\n> > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n> > > > ---\n> > > >  src/android/camera_device.cpp | 3 +++\n> > > >  src/libcamera/request.cpp     | 2 ++\n> > > >  2 files changed, 5 insertions(+)\n> > > >\n> > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> > > > index a9634f4e4198..513f000b1854 100644\n> > > > --- a/src/android/camera_device.cpp\n> > > > +++ b/src/android/camera_device.cpp\n> > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n> > > >  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n> > > >  \t}\n> > > >\n> > > > +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> > > > +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> > > > +\n> > > >  \t/*\n> > > >  \t * \\todo The timestamp used for the metadata is currently always taken\n> > > >  \t * from the first buffer (which may be the first stream) in the Request.\n> > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> > > > index a68684ef9fd3..e561ce1d5d0e 100644\n> > > > --- a/src/libcamera/request.cpp\n> > > > +++ b/src/libcamera/request.cpp\n> > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n> > > >  \tmetadata_ = new ControlList(controls::controls);\n> > > >\n> > > >  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> > > > +\n> > > > +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n> > > >  }\n> > > >\n> > > >  Request::~Request()\n> > > > --\n> > > > 2.30.0\n> > > >\n> > > > _______________________________________________\n> > > > libcamera-devel mailing list\n> > > > libcamera-devel@lists.libcamera.org\n> > > > https://lists.libcamera.org/listinfo/libcamera-devel\n> > >\n> > > --\n> > > Regards,\n> > > Niklas Söderlund\n>\n> --\n> Regards,\n> Niklas Söderlund","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 11D49BD161\n\tfor <parsemail@patchwork.libcamera.org>;\n\tTue,  2 Feb 2021 11:40:37 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 86F0568424;\n\tTue,  2 Feb 2021 12:40:36 +0100 (CET)","from relay3-d.mail.gandi.net (relay3-d.mail.gandi.net\n\t[217.70.183.195])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 992E160307\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tTue,  2 Feb 2021 12:40:35 +0100 (CET)","from uno.localdomain (93-61-96-190.ip145.fastwebnet.it\n\t[93.61.96.190]) (Authenticated sender: jacopo@jmondi.org)\n\tby relay3-d.mail.gandi.net (Postfix) with ESMTPSA id 16B3F6000B;\n\tTue,  2 Feb 2021 11:40:34 +0000 (UTC)"],"X-Originating-IP":"93.61.96.190","Date":"Tue, 2 Feb 2021 12:40:56 +0100","From":"Jacopo Mondi <jacopo@jmondi.org>","To":"Niklas =?utf-8?q?S=C3=B6derlund?= <niklas.soderlund@ragnatech.se>","Message-ID":"<20210202114056.wravl5wx6mtog77k@uno.localdomain>","References":"<20210128090454.515268-1-jacopo@jmondi.org>\n\t<YBSZr4BQrHLbrURd@oden.dyn.berto.se>\n\t<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>\n\t<YBgndGBY64hO6D6e@oden.dyn.berto.se>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<YBgndGBY64hO6D6e@oden.dyn.berto.se>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"utf-8\"","Content-Transfer-Encoding":"base64","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}},{"id":14904,"web_url":"https://patchwork.libcamera.org/comment/14904/","msgid":"<YBlL8BsvHszkx+Ti@oden.dyn.berto.se>","date":"2021-02-02T12:56:16","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":5,"url":"https://patchwork.libcamera.org/api/people/5/","name":"Niklas Söderlund","email":"niklas.soderlund@ragnatech.se"},"content":"Hi Jacopo,\n\nOn 2021-02-02 12:40:56 +0100, Jacopo Mondi wrote:\n> Hi Niklas,\n> \n> On Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote:\n> > Hi Jacopo,\n> >\n> > On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote:\n> > > Hi Niklas,\n> > >\n> > > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote:\n> > > > Hi Jacopo,\n> > > >\n> > > > Thanks for your bikeshedding opportunity :-)\n> > > >\n> > > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:\n> > > > > The current logging to track the status of a Request when running the\n> > > > > Android camera HAL provide the following information:\n> > > > >\n> > > > > When a Request is queued to libcamera:\n> > > > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > > > >\n> > > > > When a Request completes:\n> > > > > Request request.cpp:268 Request has completed - cookie: 138508601719648\n> > > > >\n> > > > > The queueing of a Request reports the number of streams it contains\n> > > > > while the completion of a Request reports the address of the associated\n> > > > > cookie.\n> > > > >\n> > > > > This makes very hard to keep track of what Requests have completed, as\n> > > > > the logging associated with a queue/complete event does not allow to identify\n> > > > > a Request easily.\n> > > > >\n> > > > > Add two more printouts to make it easier to track a Request life cycle.\n> > > > >\n> > > > > The result looks like the following trace:\n> > > > >\n> > > >\n> > > > I like the improvement, but I would alter it slightly. I think having\n> > > > the cookie value is the real value here as it makes it possible to trace\n> > > > a request.\n> > > >\n> > > > > Request request.cpp:92 Created request - cookie: 138508601718368\n> > > > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > > >\n> > > > I would remove this print to increase signal to noise. If the number of\n> > > > streams really are important I would do a 1/n thing on the line below.\n> > > > If the line is keept I would also print the cookie.\n> > >\n> > > I'm sorry I didn't fully get this one. What do you mean with \"a 1/n\n> > > thing on the line below\" ?\n> > >\n> > > Also, I think identifying how many streams the request contains is\n> > > relevant.\n> >\n> > I was thinking of if it make sens to instead of\n> >\n> >   HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >\n> > Have something like,\n> >\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >\n> > I find the later more compact while at the same time providing more\n> > information in a situation where you have to debug from a log file.\n> \n> So, that might be a matter of tastes, but:\n> 1) I try to avoid creating too long log lines\n>    I always run with terminals one side to the other, spanning more\n>    than the usual 80-cols is ok, as it's reasonable to suppose most\n>    people have larger screens nowadays, but I think we should try to\n>    be compact to ease debug/development\n> \n> 2) I try to separate information in lines, as log can be filtered,\n>    either by using libcamera log infrastructure or by piping the usual\n>    unix tools. In your example, reporting the same cookie in two lines\n>    to me add noise and makes debug more confusing than having\n>    information separated on multiple lines. I can easily filter/grep\n>    on lines I'm interested in, and I prefer one more line to parse\n>    than parsing information on a single long line\n> \n> Might be a matter of tastes indeed\n\nI agree, it's a matter of taste.\n\n> \n> >\n> > >\n> > > >\n> > > > > HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> > > >\n> > > > I would add the cookie.\n> > > >\n> > > > > ...\n> > > > > ...\n> > > > > Request request.cpp:268 Request has completed - cookie: 138508601718368\n> > > > > HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n> > > >\n> > > > I would add the cookie and possibly s/with 1 streams//\n> > >\n> > > If we remove the stream count and add the cookie, I would then rather\n> > > drop the printout in camera_device.cpp completely, as it will provide\n> > > the exact same information that the one in request.cpp provides...\n> >\n> > Is it a problem that the same information is printed at different\n> > levels? I like to see such things as it allows me to from a log file\n> > track how a request moved thru the layers. Also if I'm only interested\n> > in debugging a specific component maybe I have a\n> > LIBCAMERA_LOG_LEVELS=HAL:0 or such set?\n> \n> Ok addin the cookie to the request complete log\n> \n> >\n> > In either case as stated in my first reply this is all bikeshedding so I\n> > don't feel strongly about any of it :-)\n> >\n> > >\n> > > >\n> > > > Bikeshedding is fun but take only what you like. At the end if all lines\n> > > > have the cookie you can also take my,\n> > > >\n> > > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se>\n> \n> Thanks, I'll send a new version and I'll retain the tag, but please\n> feel free to comment on that one as well.\n\nPlease retain the tag, I'm just bikeshedding.\n\n> \n> Thanks\n>   j\n> \n> > > >\n> > > > >\n> > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n> > > > > ---\n> > > > >  src/android/camera_device.cpp | 3 +++\n> > > > >  src/libcamera/request.cpp     | 2 ++\n> > > > >  2 files changed, 5 insertions(+)\n> > > > >\n> > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> > > > > index a9634f4e4198..513f000b1854 100644\n> > > > > --- a/src/android/camera_device.cpp\n> > > > > +++ b/src/android/camera_device.cpp\n> > > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n> > > > >  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n> > > > >  \t}\n> > > > >\n> > > > > +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> > > > > +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> > > > > +\n> > > > >  \t/*\n> > > > >  \t * \\todo The timestamp used for the metadata is currently always taken\n> > > > >  \t * from the first buffer (which may be the first stream) in the Request.\n> > > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> > > > > index a68684ef9fd3..e561ce1d5d0e 100644\n> > > > > --- a/src/libcamera/request.cpp\n> > > > > +++ b/src/libcamera/request.cpp\n> > > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n> > > > >  \tmetadata_ = new ControlList(controls::controls);\n> > > > >\n> > > > >  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> > > > > +\n> > > > > +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n> > > > >  }\n> > > > >\n> > > > >  Request::~Request()\n> > > > > --\n> > > > > 2.30.0\n> > > > >\n> > > > > _______________________________________________\n> > > > > libcamera-devel mailing list\n> > > > > libcamera-devel@lists.libcamera.org\n> > > > > https://lists.libcamera.org/listinfo/libcamera-devel\n> > > >\n> > > > --\n> > > > Regards,\n> > > > Niklas Söderlund\n> >\n> > --\n> > Regards,\n> > Niklas Söderlund","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 3A841BD160\n\tfor <parsemail@patchwork.libcamera.org>;\n\tTue,  2 Feb 2021 12:56:20 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id B90D468426;\n\tTue,  2 Feb 2021 13:56:19 +0100 (CET)","from mail-lf1-x12b.google.com (mail-lf1-x12b.google.com\n\t[IPv6:2a00:1450:4864:20::12b])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 28CA160307\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tTue,  2 Feb 2021 13:56:19 +0100 (CET)","by mail-lf1-x12b.google.com with SMTP id v24so27766531lfr.7\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tTue, 02 Feb 2021 04:56:19 -0800 (PST)","from localhost (h-209-203.A463.priv.bahnhof.se. [155.4.209.203])\n\tby smtp.gmail.com with ESMTPSA id\n\tu12sm3322061lff.250.2021.02.02.04.56.17\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tTue, 02 Feb 2021 04:56:17 -0800 (PST)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=ragnatech-se.20150623.gappssmtp.com\n\theader.i=@ragnatech-se.20150623.gappssmtp.com\n\theader.b=\"mHqyGm0w\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=ragnatech-se.20150623.gappssmtp.com; s=20150623;\n\th=date:from:to:cc:subject:message-id:references:mime-version\n\t:content-disposition:content-transfer-encoding:in-reply-to;\n\tbh=A+1KYkQsFNB0De1xVkbGDYKYPiBBph+uEAkr9HF9ysI=;\n\tb=mHqyGm0wfaJSTLmyQz1UlfVaAhn8sKpQk44jbhbxdHXgBKIWntyXZRL1Lbl7qCyc90\n\tmGsnmbBpldL1XpGAQJVNVT2/UkHCxQ6YR1MJGpBJPK+27AVPdmN1ea+w5L0Bs3NjLN/0\n\tFusp1N4U6PwwzMhOqylVLzSvgJ8yXAp6RiLdLdKwuEj5j45BqEkiS7l/Tsby6BJypGiG\n\tgqEQaWLnFwot+tn77GfIkUir/5FiptazdaJhNB7ZrCLguoJrbD3WCDcLnKayZIOtc3gY\n\tPcmw7N7NjT4Xn7s/BCzsq2kZq9yz8v5ZQ0B/uRKNvNCAsQ8ObQfQ5EamFcw/MtiKxUgK\n\t+4Pg==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:date:from:to:cc:subject:message-id:references\n\t:mime-version:content-disposition:content-transfer-encoding\n\t:in-reply-to;\n\tbh=A+1KYkQsFNB0De1xVkbGDYKYPiBBph+uEAkr9HF9ysI=;\n\tb=JLzNW3EJYE1e2LzHA7M1Qdt7CqgcuSipztvgbQtaWkyLXhdUHNDcvssTfqw2NPHKkV\n\tvPgyuo5e4qIup/awsJChogKVpSNUIKZVVFSjlggwVRQYSbse1aBlXBeNbbFIKuYHWwwR\n\te5tbXSu6Rhq1PIc7kEGI3FEcbfh7kL0ODdeUHZJ5Bc8r91hZ32PPkpXk6sOmVdIw4Cvg\n\twgo8iu9g5ENje6JFchSbnPPJqMlcoX4WtMULk8d6ukg0zZBIpzSHQyuwulLeSePkLn6d\n\tMVemhvKQ/n9JzdeSMV3j+GrEjmb2KfpVwqg61ELoiUJgpbqZFhc4jsEjnT1QYXbtZMXk\n\tHTDQ==","X-Gm-Message-State":"AOAM5311ils5pA27/XSlDU5OaIJfYaMaknqOxqAUOInFTRLUi9d07lnO\n\tFu3UZj8c89J8awfRPncKehjVNhw3PQbPdw==","X-Google-Smtp-Source":"ABdhPJwI+pPK/NGgnOfMqjN52k6pQ7kHuZyUGcPBzgSBTjZRxnk/AaBPzJKuo6BhaV6MC3Y7cBzHeQ==","X-Received":"by 2002:a19:740d:: with SMTP id\n\tv13mr10586595lfe.240.1612270578309; \n\tTue, 02 Feb 2021 04:56:18 -0800 (PST)","Date":"Tue, 2 Feb 2021 13:56:16 +0100","From":"Niklas =?iso-8859-1?q?S=F6derlund?= <niklas.soderlund@ragnatech.se>","To":"Jacopo Mondi <jacopo@jmondi.org>","Message-ID":"<YBlL8BsvHszkx+Ti@oden.dyn.berto.se>","References":"<20210128090454.515268-1-jacopo@jmondi.org>\n\t<YBSZr4BQrHLbrURd@oden.dyn.berto.se>\n\t<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>\n\t<YBgndGBY64hO6D6e@oden.dyn.berto.se>\n\t<20210202114056.wravl5wx6mtog77k@uno.localdomain>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210202114056.wravl5wx6mtog77k@uno.localdomain>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"iso-8859-1\"","Content-Transfer-Encoding":"quoted-printable","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}},{"id":14928,"web_url":"https://patchwork.libcamera.org/comment/14928/","msgid":"<YBrue0HML+TrWzI+@pendragon.ideasonboard.com>","date":"2021-02-03T18:42:03","subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","submitter":{"id":2,"url":"https://patchwork.libcamera.org/api/people/2/","name":"Laurent Pinchart","email":"laurent.pinchart@ideasonboard.com"},"content":"Hi Jacopo,\n\nThank you for the patch.\n\nOn Tue, Feb 02, 2021 at 12:40:56PM +0100, Jacopo Mondi wrote:\n> On Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote:\n> > On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote:\n> > > On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote:\n> > > > Hi Jacopo,\n> > > >\n> > > > Thanks for your bikeshedding opportunity :-)\n> > > >\n> > > > On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:\n> > > > > The current logging to track the status of a Request when running the\n> > > > > Android camera HAL provide the following information:\n> > > > >\n> > > > > When a Request is queued to libcamera:\n> > > > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > > > >\n> > > > > When a Request completes:\n> > > > > Request request.cpp:268 Request has completed - cookie: 138508601719648\n> > > > >\n> > > > > The queueing of a Request reports the number of streams it contains\n> > > > > while the completion of a Request reports the address of the associated\n> > > > > cookie.\n> > > > >\n> > > > > This makes very hard to keep track of what Requests have completed, as\n> > > > > the logging associated with a queue/complete event does not allow to identify\n> > > > > a Request easily.\n> > > > >\n> > > > > Add two more printouts to make it easier to track a Request life cycle.\n> > > > >\n> > > > > The result looks like the following trace:\n> > > > >\n> > > >\n> > > > I like the improvement, but I would alter it slightly. I think having\n> > > > the cookie value is the real value here as it makes it possible to trace\n> > > > a request.\n> > > >\n> > > > > Request request.cpp:92 Created request - cookie: 138508601718368\n> > > > > HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams\n> > > >\n> > > > I would remove this print to increase signal to noise. If the number of\n> > > > streams really are important I would do a 1/n thing on the line below.\n> > > > If the line is keept I would also print the cookie.\n> > >\n> > > I'm sorry I didn't fully get this one. What do you mean with \"a 1/n\n> > > thing on the line below\" ?\n> > >\n> > > Also, I think identifying how many streams the request contains is\n> > > relevant.\n> >\n> > I was thinking of if it make sens to instead of\n> >\n> >   HAL camera_device.cpp:1776 '\\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >\n> > Have something like,\n> >\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >   HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> >\n> > I find the later more compact while at the same time providing more\n> > information in a situation where you have to debug from a log file.\n> \n> So, that might be a matter of tastes, but:\n> 1) I try to avoid creating too long log lines\n>    I always run with terminals one side to the other, spanning more\n>    than the usual 80-cols is ok, as it's reasonable to suppose most\n>    people have larger screens nowadays, but I think we should try to\n>    be compact to ease debug/development\n> \n> 2) I try to separate information in lines, as log can be filtered,\n>    either by using libcamera log infrastructure or by piping the usual\n>    unix tools. In your example, reporting the same cookie in two lines\n>    to me add noise and makes debug more confusing than having\n>    information separated on multiple lines. I can easily filter/grep\n>    on lines I'm interested in, and I prefer one more line to parse\n>    than parsing information on a single long line\n> \n> Might be a matter of tastes indeed\n\nI know this has been merged already, and there's no need to change\nanything now, but I wanted to point out that the tracing infrastructure\nis a good candidate to trace requests.\n\n> > > > > HAL camera_device.cpp:1813 '\\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)\n> > > >\n> > > > I would add the cookie.\n> > > >\n> > > > > ...\n> > > > > ...\n> > > > > Request request.cpp:268 Request has completed - cookie: 138508601718368\n> > > > > HAL camera_device.cpp:1866 '\\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams\n> > > >\n> > > > I would add the cookie and possibly s/with 1 streams//\n> > >\n> > > If we remove the stream count and add the cookie, I would then rather\n> > > drop the printout in camera_device.cpp completely, as it will provide\n> > > the exact same information that the one in request.cpp provides...\n> >\n> > Is it a problem that the same information is printed at different\n> > levels? I like to see such things as it allows me to from a log file\n> > track how a request moved thru the layers. Also if I'm only interested\n> > in debugging a specific component maybe I have a\n> > LIBCAMERA_LOG_LEVELS=HAL:0 or such set?\n> \n> Ok addin the cookie to the request complete log\n> \n> > In either case as stated in my first reply this is all bikeshedding so I\n> > don't feel strongly about any of it :-)\n> >\n> > > > Bikeshedding is fun but take only what you like. At the end if all lines\n> > > > have the cookie you can also take my,\n> > > >\n> > > > Reviewed-by: Niklas Söderlund <niklas.soderlund@ragnatech.se>\n> \n> Thanks, I'll send a new version and I'll retain the tag, but please\n> feel free to comment on that one as well.\n> \n> > > > > Signed-off-by: Jacopo Mondi <jacopo@jmondi.org>\n> > > > > ---\n> > > > >  src/android/camera_device.cpp | 3 +++\n> > > > >  src/libcamera/request.cpp     | 2 ++\n> > > > >  2 files changed, 5 insertions(+)\n> > > > >\n> > > > > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp\n> > > > > index a9634f4e4198..513f000b1854 100644\n> > > > > --- a/src/android/camera_device.cpp\n> > > > > +++ b/src/android/camera_device.cpp\n> > > > > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)\n> > > > >  \t\tstatus = CAMERA3_BUFFER_STATUS_ERROR;\n> > > > >  \t}\n> > > > >\n> > > > > +\tLOG(HAL, Debug) << \"Request completed by libcamera with \"\n> > > > > +\t\t\t<< descriptor->numBuffers_ << \" streams\";\n> > > > > +\n> > > > >  \t/*\n> > > > >  \t * \\todo The timestamp used for the metadata is currently always taken\n> > > > >  \t * from the first buffer (which may be the first stream) in the Request.\n> > > > > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp\n> > > > > index a68684ef9fd3..e561ce1d5d0e 100644\n> > > > > --- a/src/libcamera/request.cpp\n> > > > > +++ b/src/libcamera/request.cpp\n> > > > > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)\n> > > > >  \tmetadata_ = new ControlList(controls::controls);\n> > > > >\n> > > > >  \tLIBCAMERA_TRACEPOINT(request_construct, this);\n> > > > > +\n> > > > > +\tLOG(Request, Debug) << \"Created request - cookie: \" << cookie_;\n> > > > >  }\n> > > > >\n> > > > >  Request::~Request()","headers":{"Return-Path":"<libcamera-devel-bounces@lists.libcamera.org>","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 28B95BD161\n\tfor <parsemail@patchwork.libcamera.org>;\n\tWed,  3 Feb 2021 18:42:28 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 9E7AA68452;\n\tWed,  3 Feb 2021 19:42:27 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[213.167.242.64])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id AEA0268447\n\tfor <libcamera-devel@lists.libcamera.org>;\n\tWed,  3 Feb 2021 19:42:25 +0100 (CET)","from pendragon.ideasonboard.com (62-78-145-57.bb.dnainternet.fi\n\t[62.78.145.57])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id 27676580;\n\tWed,  3 Feb 2021 19:42:25 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"eNkPCzGw\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1612377745;\n\tbh=iqh4wA4+ua67LJeSgWSQwLDKuSFc9b5uj5l1qlseg7U=;\n\th=Date:From:To:Cc:Subject:References:In-Reply-To:From;\n\tb=eNkPCzGwYE0Tn0GuAv7QAhY4SieIEz5+y9UrACQS+PolavTn081pJLOl8xujpNf46\n\tZctExjCqu/6eciT8oqtaCy+bTwrov14jHqe6ROEd+nBNqTxLVtNCXv8MeRGtg32HWe\n\tXx5JU4JQYlJMWU8rJT5MtPI1cZiRSeLLir4gkf58=","Date":"Wed, 3 Feb 2021 20:42:03 +0200","From":"Laurent Pinchart <laurent.pinchart@ideasonboard.com>","To":"Jacopo Mondi <jacopo@jmondi.org>","Message-ID":"<YBrue0HML+TrWzI+@pendragon.ideasonboard.com>","References":"<20210128090454.515268-1-jacopo@jmondi.org>\n\t<YBSZr4BQrHLbrURd@oden.dyn.berto.se>\n\t<20210201103648.jwu6gnfko5gv2eby@uno.localdomain>\n\t<YBgndGBY64hO6D6e@oden.dyn.berto.se>\n\t<20210202114056.wravl5wx6mtog77k@uno.localdomain>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210202114056.wravl5wx6mtog77k@uno.localdomain>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: Improve Request life cycle\n\ttracking","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"<libcamera-devel.lists.libcamera.org>","List-Unsubscribe":"<https://lists.libcamera.org/options/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=unsubscribe>","List-Archive":"<https://lists.libcamera.org/pipermail/libcamera-devel/>","List-Post":"<mailto:libcamera-devel@lists.libcamera.org>","List-Help":"<mailto:libcamera-devel-request@lists.libcamera.org?subject=help>","List-Subscribe":"<https://lists.libcamera.org/listinfo/libcamera-devel>,\n\t<mailto:libcamera-devel-request@lists.libcamera.org?subject=subscribe>","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"utf-8\"","Content-Transfer-Encoding":"base64","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" <libcamera-devel-bounces@lists.libcamera.org>"}}]