Author Topic: Astro camera, weird artifacts when looking more closely  (Read 4738 times)

nemo

  • Newbie
  • *
  • Posts: 3
    • View Profile
Re: Astro camera, weird artifacts when looking more closely
« Reply #15 on: November 12, 2023, 01:08:08 pm »
48MP has *slightly* more detail. The sign says "Kalevan kirkko". It's *barely* more legible in this version, so the extra pixels are not completely an illusion.
 


12MP:
 


The apparent difference in detail is more likely because the second (12MP) photo simply shot it slightly sharper: either less shake, or a slightly (very slightly) different focus.  I've seen that happen between shots when testing my mirrorless cameras and lenses.

Thanks for the tests.  I've been wondering for over two years how the Astro's camera would turn out.  Unfortunately it sounds like my predictions weren't too far off:
https://www.oesf.org/forum/index.php?topic=36385.msg297221#msg297221

I don't have an Astro, and I'm done porting GCam (for the Cosmo or otherwise), period.  But I heard from some Pro1 X users that an existing GCam port works well on their devices, which also have 48MP sensors:

Google Camera Port Updates
BSG: MGC_8.4.600_A10_V13:
https://www.celsoazevedo.com/files/android/google-camera/dev-bsg/f/dl92/

Maybe it'll work on the Astro.
It works for video but not for taking still pictures. I'm having a hard time
debugging this and since I'm currently a bit stuck I will share what I found so
far in the hopes that somebody else might pick up on this.

I tested BSG MGC versions 8.9.097 (A11), 8.7.250 (A11), 8.4.600 (A10), 8.1.101
(A9) and all exhibit a very similar behavior, though 8.9 doesn't even show the
UI and crashes earliest.  Since 8.4.600 is the version referenced here I will
focus on that but 8.1.101 seems to be the one that is most configurable so it
might be worthwhile to fix that instead.  My findings are on a rooted v07b
astro android in portrait mode after setting the kernel log level to 8 (`dmesg -n 8`)
and running logcat with debug output (`logcat '*'`). Since the error possibly ruins
the camera device state I rebooted the device before conducting tests and between
installs of GCam.

Behavior after starting the app: Black image, UI is responsible but sluggish.
Switching to Video changes modes but still only a black image is seen (not
        image data; just nothing). After a while a video stream is shown -
recording normal and timelapse videos works but slowmo crashes (maybe sample
        rates are not negotiated well here?). Waiting in the camera tab results
in nothing but blackness eventually a crash. I can't switch to the front camera
app, even in video mode. App settings can be reached but I found no value that
changed this behavior (I did not do an exhaustive search, though). It happened
once that the astro rebooted when in Camera mode or in settings for too long.

After using gcam in camera mode and switching to another camera app the camera
is not responsive and no image is shown (stock app, opencamera). This suggests
to me that the device is in a bad state due to bad initialization.

If any of you can provide a bit of insight what might be the issue here I would
appreciate your help!

So let's go through the logs I thought before spending hours in despair in a
swamp of semi-useful information. Here's what I found so far after starting the
app as described above on a freshly rebooted device:


right after starting the app when the ISP is initialized the following messages appear in the kernel log
 
Code: [Select]
  [  123.063548] .(1)[474:logd.auditd]type=1400 audit(1699796437.432:275): avc: denied { read } for comm="camerahalserver" name="u:object_r:default_prop:s0" dev="tmpfs" ino=1076 scontext=u:r:mtk_hal_camera:s0 tcontext=u:object_r:default_prop:s0 tclass=file permissive=0
 
  since this is happening in the `camerahalserver` I don't think that it is relevant (assuming it is part of the system and not the app, at least I found no references in the .apk files) 


 
Code: [Select]
  [  123.063548] .(1)[474:logd.auditd]type=1400 audit(1699796437.432:275): avc: denied { read } for comm="camerahalserver" name="u:object_r:default_prop:s0" dev="tmpfs" ino=1076 scontext=u:r:mtk_hal_camera:s0 tcontext=u:object_r:default_prop:s0 tclass=file permissive=0
 
  shortly after this is happening; I tried setting it manually to `rrzo` values I found somewhere (1 being one of them IIRC) but that changed nothing. My intuition says that this is a cache value anyway and probably not relevant for the crash. 


 
Code: [Select]
  [  123.198217] -(5)[6318:camerahalserver]genirq: Flags mismatch irq 368. 00000004 (ccu) vs. 00000004 (ccu)
  [  123.200611] .(5)[6318:camerahalserver][ccu][ccu_irq_enable] fail to request ccu irq!
 
  Not sure what CCU does (Camera Control Unit?) but the flag mismatch seems a bit buggy. Unclear if relevant. 


 
Code: [Select]
  [  123.240241] .(4)[6424:camerahalserver][ISP][ISP_SetPMQOS] DFS Set clock :499
  [  123.240680] .(4)[6424:camerahalserver]moveAF:a_u4Position=430
  [  123.242478] .(2)[6318:camerahalserver][ISP][ISP_ioctl] CAM_0 viewFinder is ON (SecOn:0x0)
  [  123.243054] .(4)[6424:camerahalserver]i2c i2c-2: error:addr=0x72,irq_stat=0x3,ch_offset=0x100,mask:0x129
  [  123.243992] .(2)[6318:camerahalserver][ISP][ISP_ioctl] CAM_0_REG_TG_VF_CON 0x00000001
 

  This is where the ISP starts to set up the device and DRM, just after `cameraserver` set up auto-focus (found the motor). This is also the first error in the ISP that we can see. I²C communication seems to break for address `0x72`. [According to the device tree](https://github.com/planet-com/astro-kernel/blob/a79860700bd5f4a2522df9858692b50e2861e30d/drivers/misc/mediatek/dws/mt6873/k6873v1_64.dws#L2399) this address belongs to `CAMERA_MAIN_AF` which probably means the autofocus unit. This makes sense because the command issued is `moveAF:a_u4Position=430` - it is unclear to me if the command is bad or something else happened. Focussing in video mode works, not sure.

  What follows is a huge dump of I2C registers in the wake of the error. There's one further attempt to set the autofocus position (moveAF with same position) but that seems to fail as well. After that the stack is reset:

 
Code: [Select]
[  123.244926] .(4)[6424:camerahalserver]i2c_dump_info: +++++++++++++++++++
[  123.244930] .(4)[6424:camerahalserver]I2C structure:
    [I2C]Clk=24960000,Id=2,Op=0x1,Irq_stat=0x3,Total_len=0x2
    [I2C]Trans_len=0x2,Trans_num=0x1,Trans_auxlen=0x0,
    [I2C]speed=400000,Trans_stop=1,cg_cnt=1,hs_only=0,
    [I2C]ch_offset=0x100,ch_offset_default=0x100
[  123.244934] .(4)[6424:camerahalserver]base addr:0x00000000fde4147d
[  123.247093] .(4)[6424:camerahalserver]I2C register:
    [I2C]SLAVE_ADDR=0xe4,INTR_MASK=0x0,INTR_STAT=0x0,
    [I2C]CONTROL=0x28,TRANSFER_LEN=0x2,TRANSAC_LEN=0x1,
    [I2C]DELAY_LEN=0xa,TIMING=0x405,LTIMING=0x23,START=0x2
    [I2C]FIFO_STAT=0x0,IO_CONFIG=0x3,HS=0x0
    [I2C]DCM_EN=0x0,DEBUGSTAT=0x700,EXT_CONF=0x1801
    [I2C]TRANSFER_LEN_AUX=0x1,OFFSET_DMA_FSM_DEBUG=0x8200
    [I2C]OFFSET_MCU_INTR=0x1
[  123.261705] .(7)[381:kworker/7:2][ISP][ISP_BH_Workqueue] [123.260901],,CAM_A P1_SOF_0_0(0x00008800_0x00010001,0x00008800_0x00010001,0xff786000,0xff01d000,0x1),int_us:0,cq:0xf6b5a000_0x00000000_0x00000000,DMA(0x0_0x0,0x0_0x0,0x2fffff04_0x2fffff04,0x2fffff04_0x2fffff04)FLKO(0x0,0x0,0xf468d000,0xf468d000)
[  123.261736] .(4)[6424:camerahalserver]before enable DMA register(0xffffff800cb15180):
    [I2C]INT_FLAG=0x0,INT_EN=0x0,EN=0x0,RST=0x0,
    [I2C]STOP=0x0,FLUSH=0x0,CON=0x1c,
    [I2C]TX_MEM_ADDR=0x194ec000, RX_MEM_ADDR=0x194ec100
    [I2C]TX_LEN=0x11a,RX_LEN=0x100,INT_BUF_SIZE=0x0,
    [I2C]DEBUGSTA=0x2020200,TX_MEM_ADDR2=0x2, RX_MEM_ADDR2=0x2
[  123.261745] .(4)[6424:camerahalserver]DMA register(0x0000000004dae34c):
    [I2C]INT_FLAG=0x1,INT_EN=0x0,EN=0x0,RST=0x0,
    [I2C]STOP=0x0,FLUSH=0x0,CON=0x1c,
    [I2C]TX_MEM_ADDR=0x194ec11a, RX_MEM_ADDR=0x194ec100,
    [I2C]TX_LEN=0x11a,RX_LEN=x100,INT_BUF_SIZE=0x0,
    [I2C]DEBUGSTA=0x1a1a1a00,TX_MEM_ADDR2=0x2, RX_MEM_ADDR2=0x2
[  123.263964] .(4)[6424:camerahalserver]i2c_dump_info: -----------------------
[  123.268506] .(4)[6424:camerahalserver]i2c i2c-2: last transfer info:
[  123.268509] .(4)[6424:camerahalserver]i2c i2c-2: [00] [  123.243050] SLAVE_ADDR=e4,INTR_STAT=3,CONTROL=28,FIFO_STAT=1,DEBUGSTAT=300, tmo=500
[  123.268511] .(4)[6424:camerahalserver]i2c i2c-2: [01] [  123.122312] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268513] .(4)[6424:camerahalserver]i2c i2c-2: [02] [  123.101077] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268515] .(4)[6424:camerahalserver]i2c i2c-2: [03] [  123.100926] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268517] .(4)[6424:camerahalserver]i2c i2c-2: [04] [  123.100778] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268519] .(4)[6424:camerahalserver]i2c i2c-2: [05] [  123.100625] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268522] .(4)[6424:camerahalserver]i2c i2c-2: [06] [  123.100474] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268523] .(4)[6424:camerahalserver]i2c i2c-2: [07] [  123.100326] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268526] .(4)[6424:camerahalserver]i2c i2c-2: [08] [  123.100181] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268527] .(4)[6424:camerahalserver]i2c i2c-2: [09] [  123.100028] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268546] .(4)[6424:camerahalserver]i2c i2c-2: I2C CCU register:
    [I2C]SLAVE_ADDR=0xff,INTR_MASK=0x1ff,
    [I2C]INTR_STAT=0x0,CONTROL=0x0,
    [I2C]TRANSFER_LEN=0x0, TRANSAC_LEN=0x0,DELAY_LEN=0x0
    [I2C]TIMING=0x0,LTIMING=0x0,START=0x0,FIFO_STAT=0x0,
    [I2C]IO_CONFIG=0x93,HS=0x0,DCM_EN=0x0,DEBUGSTAT=0x700,
    [I2C]EXT_CONF=0x0,TRANSFER_LEN_AUX=0x0
    [I2C]OFFSET_DMA_FSM_DEBUG=0x8200,OFFSET_MCU_INTR=0x3
[  123.268548] .(4)[6424:camerahalserver]i2c i2c-2: i2c_gpio_dump_info +++++++++++++++++++
[  123.268553] .(4)[6424:camerahalserver]i2c i2c-2: I2C gpio structure:\x0a[I2C]EH_CFG=0x3fffffff,PU_CFG=0xff812e00,RSEL_CFG=0xffffff
[  123.268555] .(4)[6424:camerahalserver]i2c i2c-2: addr:0x72,ACK error
[  123.268556] .(4)[6424:camerahalserver]i2c i2c-2: trans done with error
[  123.268643] .(4)[6424:camerahalserver]i2c i2c-2: error:addr=0x72,irq_stat=0x3,ch_offset=0x100,mask:0x129
[  123.268645] .(4)[6424:camerahalserver]i2c_dump_info: +++++++++++++++++++
[  123.268648] .(4)[6424:camerahalserver]I2C structure:
    [I2C]Clk=24960000,Id=2,Op=0x1,Irq_stat=0x3,Total_len=0x1
    [I2C]Trans_len=0x1,Trans_num=0x1,Trans_auxlen=0x0,
    [I2C]speed=400000,Trans_stop=1,cg_cnt=1,hs_only=0,
    [I2C]ch_offset=0x100,ch_offset_default=0x100
[  123.268649] .(4)[6424:camerahalserver]base addr:0x00000000fde4147d
[  123.268667] .(4)[6424:camerahalserver]I2C register:
    [I2C]SLAVE_ADDR=0xe4,INTR_MASK=0x0,INTR_STAT=0x0,
    [I2C]CONTROL=0x28,TRANSFER_LEN=0x1,TRANSAC_LEN=0x1,
    [I2C]DELAY_LEN=0xa,TIMING=0x405,LTIMING=0x23,START=0x2
    [I2C]FIFO_STAT=0x0,IO_CONFIG=0x3,HS=0x0
    [I2C]DCM_EN=0x0,DEBUGSTAT=0x700,EXT_CONF=0x1801
    [I2C]TRANSFER_LEN_AUX=0x1,OFFSET_DMA_FSM_DEBUG=0x8200
    [I2C]OFFSET_MCU_INTR=0x1
[  123.268670] .(4)[6424:camerahalserver]before enable DMA register(0xffffff800cb15180):
    [I2C]INT_FLAG=0x0,INT_EN=0x0,EN=0x0,RST=0x0,
    [I2C]STOP=0x0,FLUSH=0x0,CON=0x1c,
    [I2C]TX_MEM_ADDR=0x194ec000, RX_MEM_ADDR=0x194ec100
    [I2C]TX_LEN=0x11a,RX_LEN=0x100,INT_BUF_SIZE=0x0,
    [I2C]DEBUGSTA=0x2020200,TX_MEM_ADDR2=0x2, RX_MEM_ADDR2=0x2
[  123.268675] .(4)[6424:camerahalserver]DMA register(0x0000000004dae34c):
    [I2C]INT_FLAG=0x1,INT_EN=0x0,EN=0x0,RST=0x0,
    [I2C]STOP=0x0,FLUSH=0x0,CON=0x1c,
    [I2C]TX_MEM_ADDR=0x194ec11a, RX_MEM_ADDR=0x194ec100,
    [I2C]TX_LEN=0x11a,RX_LEN=x100,INT_BUF_SIZE=0x0,
    [I2C]DEBUGSTA=0x1a1a1a00,TX_MEM_ADDR2=0x2, RX_MEM_ADDR2=0x2
[  123.268676] .(4)[6424:camerahalserver]i2c_dump_info: -----------------------
[  123.268677] .(4)[6424:camerahalserver]i2c i2c-2: last transfer info:
[  123.268679] .(4)[6424:camerahalserver]i2c i2c-2: [00] [  123.268642] SLAVE_ADDR=e4,INTR_STAT=3,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268681] .(4)[6424:camerahalserver]i2c i2c-2: [01] [  123.243050] SLAVE_ADDR=e4,INTR_STAT=3,CONTROL=28,FIFO_STAT=1,DEBUGSTAT=300, tmo=500
[  123.268682] .(4)[6424:camerahalserver]i2c i2c-2: [02] [  123.122312] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268684] .(4)[6424:camerahalserver]i2c i2c-2: [03] [  123.101077] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268686] .(4)[6424:camerahalserver]i2c i2c-2: [04] [  123.100926] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268688] .(4)[6424:camerahalserver]i2c i2c-2: [05] [  123.100778] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268690] .(4)[6424:camerahalserver]i2c i2c-2: [06] [  123.100625] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268691] .(4)[6424:camerahalserver]i2c i2c-2: [07] [  123.100474] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268693] .(4)[6424:camerahalserver]i2c i2c-2: [08] [  123.100326] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268695] .(4)[6424:camerahalserver]i2c i2c-2: [09] [  123.100181] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268712] .(4)[6424:camerahalserver]i2c i2c-2: I2C CCU register:
    [I2C]SLAVE_ADDR=0xff,INTR_MASK=0x1ff,
    [I2C]INTR_STAT=0x0,CONTROL=0x0,
    [I2C]TRANSFER_LEN=0x0, TRANSAC_LEN=0x0,DELAY_LEN=0x0
    [I2C]TIMING=0x0,LTIMING=0x0,START=0x0,FIFO_STAT=0x0,
    [I2C]IO_CONFIG=0x93,HS=0x0,DCM_EN=0x0,DEBUGSTAT=0x700,
    [I2C]EXT_CONF=0x0,TRANSFER_LEN_AUX=0x0
    [I2C]OFFSET_DMA_FSM_DEBUG=0x8200,OFFSET_MCU_INTR=0x3
[  123.268714] .(4)[6424:camerahalserver]i2c i2c-2: i2c_gpio_dump_info +++++++++++++++++++
[  123.268719] .(4)[6424:camerahalserver]i2c i2c-2: I2C gpio structure:\x0a[I2C]EH_CFG=0x3fffffff,PU_CFG=0xff812e00,RSEL_CFG=0xffffff
[  123.268720] .(4)[6424:camerahalserver]i2c i2c-2: addr:0x72,ACK error
[  123.268721] .(4)[6424:camerahalserver]i2c i2c-2: trans done with error
[  123.268799] .(4)[6424:camerahalserver]i2c i2c-2: error:addr=0x72,irq_stat=0x3,ch_offset=0x100,mask:0x129
[  123.268800] .(4)[6424:camerahalserver]i2c_dump_info: +++++++++++++++++++
[  123.268803] .(4)[6424:camerahalserver]I2C structure:
    [I2C]Clk=24960000,Id=2,Op=0x1,Irq_stat=0x3,Total_len=0x1
    [I2C]Trans_len=0x1,Trans_num=0x1,Trans_auxlen=0x0,
    [I2C]speed=400000,Trans_stop=1,cg_cnt=1,hs_only=0,
    [I2C]ch_offset=0x100,ch_offset_default=0x100
[  123.268804] .(4)[6424:camerahalserver]base addr:0x00000000fde4147d
[  123.268820] .(4)[6424:camerahalserver]I2C register:
    [I2C]SLAVE_ADDR=0xe4,INTR_MASK=0x0,INTR_STAT=0x0,
    [I2C]CONTROL=0x28,TRANSFER_LEN=0x1,TRANSAC_LEN=0x1,
    [I2C]DELAY_LEN=0xa,TIMING=0x405,LTIMING=0x23,START=0x2
    [I2C]FIFO_STAT=0x0,IO_CONFIG=0x3,HS=0x0
    [I2C]DCM_EN=0x0,DEBUGSTAT=0x700,EXT_CONF=0x1801
    [I2C]TRANSFER_LEN_AUX=0x1,OFFSET_DMA_FSM_DEBUG=0x8200
    [I2C]OFFSET_MCU_INTR=0x1
[  123.268823] .(4)[6424:camerahalserver]before enable DMA register(0xffffff800cb15180):
    [I2C]INT_FLAG=0x0,INT_EN=0x0,EN=0x0,RST=0x0,
    [I2C]STOP=0x0,FLUSH=0x0,CON=0x1c,
    [I2C]TX_MEM_ADDR=0x194ec000, RX_MEM_ADDR=0x194ec100
    [I2C]TX_LEN=0x11a,RX_LEN=0x100,INT_BUF_SIZE=0x0,
    [I2C]DEBUGSTA=0x2020200,TX_MEM_ADDR2=0x2, RX_MEM_ADDR2=0x2
[  123.268828] .(4)[6424:camerahalserver]DMA register(0x0000000004dae34c):
    [I2C]INT_FLAG=0x1,INT_EN=0x0,EN=0x0,RST=0x0,
    [I2C]STOP=0x0,FLUSH=0x0,CON=0x1c,
    [I2C]TX_MEM_ADDR=0x194ec11a, RX_MEM_ADDR=0x194ec100,
    [I2C]TX_LEN=0x11a,RX_LEN=x100,INT_BUF_SIZE=0x0,
    [I2C]DEBUGSTA=0x1a1a1a00,TX_MEM_ADDR2=0x2, RX_MEM_ADDR2=0x2
[  123.268829] .(4)[6424:camerahalserver]i2c_dump_info: -----------------------
[  123.268830] .(4)[6424:camerahalserver]i2c i2c-2: last transfer info:
[  123.268832] .(4)[6424:camerahalserver]i2c i2c-2: [00] [  123.268798] SLAVE_ADDR=e4,INTR_STAT=3,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268834] .(4)[6424:camerahalserver]i2c i2c-2: [01] [  123.268642] SLAVE_ADDR=e4,INTR_STAT=3,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268835] .(4)[6424:camerahalserver]i2c i2c-2: [02] [  123.243050] SLAVE_ADDR=e4,INTR_STAT=3,CONTROL=28,FIFO_STAT=1,DEBUGSTAT=300, tmo=500
[  123.268837] .(4)[6424:camerahalserver]i2c i2c-2: [03] [  123.122312] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268839] .(4)[6424:camerahalserver]i2c i2c-2: [04] [  123.101077] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268841] .(4)[6424:camerahalserver]i2c i2c-2: [05] [  123.100926] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268842] .(4)[6424:camerahalserver]i2c i2c-2: [06] [  123.100778] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268844] .(4)[6424:camerahalserver]i2c i2c-2: [07] [  123.100625] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268846] .(4)[6424:camerahalserver]i2c i2c-2: [08] [  123.100474] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268847] .(4)[6424:camerahalserver]i2c i2c-2: [09] [  123.100326] SLAVE_ADDR=34,INTR_STAT=1,CONTROL=28,FIFO_STAT=0,DEBUGSTAT=700, tmo=500
[  123.268864] .(4)[6424:camerahalserver]i2c i2c-2: I2C CCU register:
    [I2C]SLAVE_ADDR=0xff,INTR_MASK=0x1ff,
    [I2C]INTR_STAT=0x0,CONTROL=0x0,
    [I2C]TRANSFER_LEN=0x0, TRANSAC_LEN=0x0,DELAY_LEN=0x0
    [I2C]TIMING=0x0,LTIMING=0x0,START=0x0,FIFO_STAT=0x0,
    [I2C]IO_CONFIG=0x93,HS=0x0,DCM_EN=0x0,DEBUGSTAT=0x700,
    [I2C]EXT_CONF=0x0,TRANSFER_LEN_AUX=0x0
    [I2C]OFFSET_DMA_FSM_DEBUG=0x8200,OFFSET_MCU_INTR=0x3
[  123.268866] .(4)[6424:camerahalserver]i2c i2c-2: i2c_gpio_dump_info +++++++++++++++++++
[  123.268871] .(4)[6424:camerahalserver]i2c i2c-2: I2C gpio structure:
    [I2C]EH_CFG=0x3fffffff,PU_CFG=0xff812e00,RSEL_CFG=0xffffff
[  123.268872] .(4)[6424:camerahalserver]i2c i2c-2: addr:0x72,ACK error
[  123.268873] .(4)[6424:camerahalserver]i2c i2c-2: trans done with error
[  123.281606] .(4)[6428:AFthread]moveAF:a_u4Position=430
[  123.294048] .(0)[930:camerahalserver][ISP][SV_SetPMQOS] module:5 BW_clr
[  123.294281] .(7)[381:kworker/7:2][ISP][ISP_BH_Workqueue] [123.294221]CAM_A P1_DON_0(0x00008800_0x00000101,0x00008800_0x00000101)dma done(0xbf7b5,0x0,0x0)exe_us:32115,CAMA Lost p1 done_1 (0x1): ,CAM_A P1_SOF_1_1(0x00008800_0x02000101,0x00008800_0x02000101,0xff786000,0xff01d000,0x1),int_us:33321,cq:0xf6b5a000_0x00000000_0x00000000,DMA(0x0_0x0,0x0_0x0,0x2fffff04_0x2fffff04,0x2fffff04_0x2fffff04)FLKO(0x0,0x0,0xf466d000,0xf466d000)
[  123.294960] .(2)[367:charger_thread]Vbat=4278,Ibat=-6713,I=0,VChr=4862,T=24,Soc=100:100,CT:1:1 hv:0 pd:0:1
[  123.296224] .(0)[930:camerahalserver][ISP][ISP_ioctl] CAMSV_2 viewFinder is OFF
[  123.299445] .(0)[930:camerahalserver][ISP][ISP_ioctl] CAMSV_2_REG_TG_VF_CON 0x00000000
[  123.301819] .(2)[367:charger_thread]mt635x-auxadc mt635x-auxadc: name:VBIF, channel=11, adc_out=0x9fb, adc_result=2807
[  123.302694] .(2)[367:charger_thread][ISP][ISP_FLUSH_IRQ] type(0)userKey(2)St_type(0)St(0x40)
[  123.306197] .(0)[930:camerahalserver][ISP][ISP_ioctl] CAM_0 viewFinder is OFF
[  123.314871] .(0)[930:camerahalserver][ISP][ISP_ioctl] CAM_0_REG_TG_VF_CON 0x00000000
[  123.349450] .(0)[930:camerahalserver][ISP][ISP_SetPMQOS] module:0 bw_clr
[  123.352965] .(0)[930:camerahalserver][ISP][ISP_SetPMQOS] DFS_clr
   


  After that we go in circles I think.

 
Code: [Select]
    [  124.078728] .(5)[6268:3ATHREAD][ISP][ISP_ioctl] CAMSV_5 viewFinder is ON
    [  124.082900] .(5)[6268:3ATHREAD][ISP][ISP_ioctl] CAMSV_5:[DMA_EN]:0x10
    [  124.083785] .(5)[6268:3ATHREAD][ISP][ISP_ioctl] CAMSV_2_REG_TG_VF_CON 0x00000001
    [  124.084804] .(7)[6461:IspEnqThd_STT_S][ISP][ISP_REGISTER_IRQ_USERKEY] User(CamsvStatisticPipe_Thread_12)key(2)
    [  124.087340] .(7)[6268:3ATHREAD][ISP][ISP_REGISTER_IRQ_USERKEY] User(AFThread)key(3)
    [  124.088452] .(7)[6268:3ATHREAD][ISP][ISP_REGISTER_IRQ_USERKEY] User(Sw_P1_Done)key(4)
    [  124.089475] .(7)[6268:3ATHREAD][ISP][ISP_REGISTER_IRQ_USERKEY] User(EventThreadVSIrq)key(5)
    [  124.091099] .(7)[381:kworker/7:2][ISP][ISP_BH_Workqueue]
[124.088403]CAMSV2:int_err:0x0_0x10000\
    [124.088427]CAMSV2:int_err:0x0_0x10000
 

  (Note that the `ISP_BH_Workqueue` messages carry messages with their own timestamps since execution is asynchronous, I indented the lines to highlight that these sub-messages are part of the work queue kernel messages.)

  According to the [astro kernel source](https://github.com/planet-com/astro-kernel/blob/a79860700bd5f4a2522df9858692b50e2861e30d/drivers/misc/mediatek/cameraisp/src/mt6873/camera_isp.c#L8138) this is definitely an error (`0x1000`) for the state `ISP_IRQ_TYPE_INT_CAMSV_2_ST`. According to [this mailing list entry](https://lore.kernel.org/all/20230630100321.1951138-4-jstephan@baylibre.com/) CAMSV is a set of DMA engines (so there are multiple ways of getting data fast from the camera). So what I gather from this is that CAMSV2 setup failed, if this is a probing setup or a setup we depend on I don't know. Maybe multiple DMA settings are used at once, one for the view finder, one for taking pictures - `CAMSV_5` and `CAMSV_2` respectively?

 
Code: [Select]
[  124.102976] .(4)[6346:camerahalserver][ISP][ISP_ioctl] CAM_0 viewFinder is ON (SecOn:0x0)
[  124.104968] .(4)[6346:camerahalserver][ISP][ISP_ioctl] CAM_0_REG_TG_VF_CON 0x00000001
[  124.106022] .(5)[6451:IspEnqThd_TG1][ISP][ISP_REGISTER_IRQ_USERKEY] User(NormalPipe_Thread)key(6)

[  124.106819] .(4)[313:kworker/4:2][ISP][ISP_BH_Workqueue]
[124.106761]\x5c,\x5c,CAM_A P1_SOF_0_0(0x00008800_0x00010001,0x00008800_0x00010001,0xf6a19000,0xf51cb000,0x1),int_us:0,cq:0xf6af0000_0xf519a000_0xf5123000,DMA(0x817b1_0x817b1,0x817b1_0x817b1,0x2c41f00_0x2c41f00,0x2c41f00_0x2c41f00)FLKO(0x0,0x0,0xf4bce000,0xf4bce000)
   
[  124.110238] .(6)[8:rcu_preempt][ISP][ISP_BH_Workqueue]
[124.110087]CAM_B:raw_int_err:0x800000, raw_int5_wrn:0x0,lsci_wrn:0x0
[124.110087]int3_en:0x0|0x300,int4_en:0x0|0x0\
    [124.110087]camsys:0x3c032
    [124.110087]CAM_B:IMGO:0xffff80a0,LTMSO:0 xffff0000,RRZO:0xffff0000,LCSO=0xffff0000,LCESHO=0xffff0000,AAO=0xffff82a0,
[124.110087]AAHO=0xffff8280,FLKO=0xffff82a0,UFEO=0xffff0000,AFO=0xffff82a0,UFGO=0xffff0000,RSSO=0xffff0000
    [124.110087]EISO=0xffff0000,YUVBO=0xffff82a0,TSFSO=0xffff8280,PDO=0xffff0000,CRZO=0xffff82a0,CRZBO=0xffff0000
[124.110087]YUVCO=0xffff0000,CRZO_R2
   
[  124.110246] -(6)[8:rcu_preempt][ISP][ISP_BH_Workqueue] 0xffff0000,RSSO_R2=0xffff0000,YUVO=0xffff82a0
[124.110087]DMA_DBG_SEL=0x0,TOP_DBG_PORT=0x0
    [124.110087]CAM_B:RAWI=0xffff0000,BPCI:0xffff0000,LSCI=0xffff0044,BPCI_R2=0xffff0000,PDI=0xffff0000,UFDI_R2=0xffff0000,
[124.110087]CAM_B Module[5] Req/Rdy Status: 0=(0x00000000 0x00000000)
    [124.110087]1=(0x00000000 0x00000000), 2=(0x00000000 0x00000000)
    [124.110087]3=(0x00000000 0x00000000), 4=(0x00000000 0x00000000)
    [124.110087]5=(0x00000000 0x00000000), 6=(0x00000000 0x00000000)
   
[  124.110299] .(0)[295:kworker/0:2][ISP][ISP_BH_Workqueue]
[124.110091]CAM_C:raw_int_err:0x800000, raw_int5_wrn:0x0,lsci_wrn:0x0
    [124.110091]int3_en:0x0|0x300,int4_en:0x0|0x0
    [124.110091]camsys:0x3c032
[124.110091]CAM_C:IMGO:0xffff80a0,LTMSO:0xffff0000,RRZO:0xffff0000,LCSO=0xffff0000,LCESHO=0xffff0000,AAO=0xffff82a0,
    [124.110091]AAHO=0xffff8280,FLKO=0xffff82a0,UFEO=0xffff0000,AFO=0xffff82a0,UFGO=0xffff0000,RSSO=0xffff0000\x0a[124.110091]EISO=0xffff0000,YUVBO=0xffff82a0,TSFSO=0xffff8280,PDO=0xffff0000,CRZO=0xffff82a0,CRZBO=0xffff0000
    [124.110091]YUVCO=0xffff0000,CRZO_R2
 

  I think this iterates through possible multi-camera settings but only the initialization of phase 1 of camera A seems to go through without the `0x80000` error. I think that's OK.
  What can be seen though is that `CAM_0` instead of `CAMSV_2` is set up with `REG_TG_VF_CON=0x1`; I'd say this is a hint that it serves as an alternative to `CAMSV_2` which initialization failed before (init. view finder, set same registers, use different means).

 
Code: [Select]
[  124.111028] .(4)[313:kworker/4:2][ISP][ISP_BH_Workqueue] [124.110119]CAM_A:raw_int_err:0x800020, raw_int5_wrn:0x0,lsci_wrn:0x0
[124.110119]int3_en:0x3ff|0x300,int4_en:0x3fffff|0x0
[124.110119]camsys:0x3c032
[124.110119]CAM_A:IMGO:0xffff80a0,LTMSO:0xffff8280,RRZO:0xffff80a0,LCSO=0xffff82a0,LCESHO=0xffff82a0,AAO=0xffff82a0,[124.110119]AAHO=0xffff8280,FLKO=0xffff82a0,UFEO=0xffff0000,AFO=0xffff82a0,UFGO=0xffff0000,RSSO=0xffff82a0\x0a[124.110119]EISO=0xffff8280,YUVBO=0xffff82a0,TSFSO=0xffff8280,PDO=0xffff0000,CRZO=0xffff82a0,CRZBO=0xffff0000
[124.110119]YUVCO=0xffff0000,
 

  *Something* failed for camera A as well (`err=0x800020`) but I found no reference to that error so far. In the kernel source the name of this state is `ISP_IRQ_TYPE_INT_CAM_A_ST` - the second `_ST` state that errors. I wonder if this is an attempt to fall back from the `CAMSV2` error.

 
Code: [Select]
[  124.111034] .(6)[6451:IspEnqThd_TG1][ISP][ISP_BH_Workqueue] RZO_R2=0xffff0000,RSSO_R2=0xffff0000,YUVO=0xffff82a0
    [124.110119]DMA_DBG_SEL=0x0,TOP_DBG_PORT=0x0
    [124.110119]CAM_A:RAWI=0xffff0000,BPCI:0xffff0000,LSCI=0xffff0044,BPCI_R2=0xffff0000,PDI=0xffff0000,UFDI_R2=0xffff0000,
    [124.110119]CAM_A Module[4] Req/Rdy Status: 0=(0x00000000 0x00000000)
    [124.110119]1=(0x00000000 0x00000000), 2=(0x00000000 0x00000000)
    [124.110119]3=(0x00000000 0x00000000), 4=(0x00000000 0x00000000)
    [124.110119]5=(0x00000000 0x00000000), 6=(0x00000000 0x00000000)
[  124.112836] .(6)[6451:IspEnqThd_TG1][mmdvfs]cam_bw(1446) > camera_max_bw(1143)
[  124.112882] .(6)[6451:IspEnqThd_TG1][mmdvfs]cam_bw(1910) > camera_max_bw(1143)
[  124.112901] .(6)[6451:IspEnqThd_TG1][mmdvfs]cam_bw(2408) > camera_max_bw(1143)
   

   This happens directly after the previous error. Note that the attempted camera bandwidth seems way to high - I have no clue who does this but I would have thought that such properties can be queried and no end-user application should make wrong assumptions about this. Not sure how this can be wrong but apparently it is. Not sure if this is a problem, though.

   In any case the request and ready status for every module is `0x0`. I have no reference but I would have assumed there will be a difference between modules that exist and those who don't. Not sure, though.

 
Code: [Select]
  [  124.215687] .(2)[146:kworker/2:1][ISP][ISP_BH_Workqueue]
      [124.114309]CAM_A:raw_int_err:0x800020, raw_int5_wrn:0x0,lsci_wrn:0x0
      [124.114309]int3_en:0x3ff|0x0,int4_en:0x3fffff|0x0
      [124.114309]camsys:0x3c032
      [124.114309]CAM_A:IMGO:0xffff80a0,LTMSO:0xffff8280,RRZO:0xffff0000,LCSO=0xffff82a0,LCESHO=0xffff82a0,AAO=0xffff82a0,
      [124.114309]AAHO=0xffff8280,FLKO=0xffff82a0,UFEO=0xffff0000,AFO=0xffff82a0,UFGO=0xffff0000,RSSO=0xffff0000
      [124.114309]EISO=0xffff0000,YUVBO=0xffff0000,TSFSO=0xffff82a0,PDO=0xffff0000,CRZO=0xffff0000,CRZBO=0xffff0000
      [124.114309]YUVCO=0xffff0000,CR
  [  124.217381] .(2)[146:kworker/2:1][ISP][ISP_BH_Workqueue] O_R2=0xffff0000,RSSO_R2=0xffff0000,YUVO=0xffff0000
      [124.114309]DMA_DBG_SEL=0x30306,TOP_DBG_PORT=0x0
   [124.114309]CAM_A:RAWI=0xffff0000,BPCI:0xffff0000,LSCI=0xffff0044,BPCI_R2=0xffff0000,PDI=0xffff0000,UFDI_R2=0xffff0000,
      [124.114309]CAM_A Module[4] Req/Rdy Status: 0=(0x00000000 0x00000000)
      [124.114309]1=(0x00000000 0x00000000), 2=(0x00000000 0x00000000)
      [124.114309]3=(0x00000000 0x00000000), 4=(0x00000000 0x00000000)
      [124.114309]5=(0x00000000 0x00000000), 6=(0x00000000 0x00000000)
  [  124.225182] .(2)[146:kworker/2:1][ISP][ISP_BH_Workqueue]
      [124.114309]CAMA PHY cqcnt:1 != VIR cqcnt:2, IrqStatus:0x1
      [124.114309]\x5c,\x5c,CAM_A P1_SOF_2_0(0x00008800_0x00010001,0x00008800_0x00010001,0xf6a19000,0xf51cb000,0x1),int_us:104501,cq:0xf6abb000_0xf5189000_0xf5112000,DMA(0x817b1_0x817b1,0x817b1_0x817b1,0x2c41f00_0x2c41f00,0x2c41f00_0x2c41f00)FLKO(0x0,0x0,0xf4bce000,0xf4bce000)
      [124.214827]CAMA PHY cqcnt:1 != VIR cqcnt:2, IrqStatus:0x3
      [124.214827]\x5c,\x5c,CAM_A P1_SOF_3_0(0x00008800_0x00010001,0x00008800_0x00010001,0xf6a19000,0xf51cb000,0x1),int_us:46,cq:0xf6abb000
  [  124.231743] .(2)[146:kworker/2:1][ISP][ISP_BH_Workqueue] 0xf5189000_0xf5112000,DMA(0x817b1_0x817b1,0x817b1_0x817b1,0x2c41f00_0x2c41f00,0x2c41f00_0x2c41f00)FLKO(0x0,0x0,0xf4bce000,0xf4bce000)
      [124.224434]CAMA PHY cqcnt:1 != VIR cqcnt:2, IrqStatus:0x3
      [124.224434]\x5c,\x5c,CAM_A P1_SOF_4_0(0x00008800_0x00010001,0x00008800_0x00010001,0xf6a19000,0xf51cb000,0x1),int_us:9610,cq:0xf6abb000_0xf5189000_0xf5112000,DMA(0x817b1_0x817b1,0x817b1_0x817b1,0x2c41f00_0x2c41f00,0x2c41f00_0x2c41f00)FLKO(0x0,0x0,0xf4bce000,0xf4bce000)
      [124.225754]CAMA PHY cqcnt:1 != VIR cqcnt:2, IrqStatus
  [  124.238607] .(2)[146:kworker/2:1][ISP][ISP_BH_Workqueue] 0x1
      [124.225754]\x5c,\x5c,CAM_A P1_SOF_5_0(0x00008800_0x00010001,0x00008800_0x00010001,0xf6a19000,0xf51cb000,0x1),int_us:1321,cq:0xf6abb000_0xf5189000_0xf5112000,DMA(0x817b1_0x817b1,0x817b1_0x817b1,0x2c41f00_0x2c41f00,0x2c41f00_0x2c41f00)FLKO(0x0,0x0,0xf4bce000,0xf4bce000)
      [124.230490]CAMA PHY cqcnt:1 != VIR cqcnt:2, IrqStatus:0x1
      [124.230490]\x5c,\x5c,CAM_A P1_SOF_6_0(0x00008800_0x00010001,0x00008800_0x00010001,0xf6a19000,0xf51cb000,0x1),int_us:4735,cq:0xf6abb000_0xf5189000_0xf5112000,DMA(0x817b1_0x817b1,0x817b1_0x81
 
   
  These are the last entries that matter. This will repeat until the interrupt handler runs in a timeout. Then it will try again, leading to the same errors. Then it will shutdown and the abstraction layer above it will try again, leading to the whole process being started anew with much the same outcome. 
  The `PHY cqcnt != VIR cqcnt` is probably the comparison of the 'completion queue counts' of the device (`PHY`) and the driver (`VIR`) meaning that only one command of two submitted commands succeeded. 
« Last Edit: November 12, 2023, 07:04:35 pm by nemo »