raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.14k stars 4.99k forks source link

I2C issues with 5.4 + TC358743 #3602

Closed mdevaev closed 4 years ago

mdevaev commented 4 years ago

Describe the bug After updating the kernel from version 4.19.118 to 5.4.35 an attempt to get an image from the tc358743 device twice in a row (reopen device file) results to I2C timeouts. In some cases, this leads to a hang (see log1), sometimes it causes errors when working with the MMC card and a reboot (see log2).

UPD: The first message was not entirely accurate. The problem occur when the first reading process is interrupted. That is, I run yavta, press Ctrl+C and immediately got a dead kernel. I played around with yavta a bit and found out that the problem occurs either when closing /dev/video0 or when executing ioctl VIDIOC_STREAMOFF. I think the tc358743 driver is trying to command something over I2C, and everything stops working.

/UPD

[   79.678547] ------------[ cut here ]------------
[   79.678554] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   79.678569] tc358743 10-000f: i2c_wr: writing register 0x4 from 0xf failed
[   79.683241] WARNING: CPU: 3 PID: 34 at drivers/firmware/raspberrypi.c:63 rpi_firmware_transaction+0xe8/0x124
[   79.705713] Firmware transaction timeout
[   79.705715] Modules linked in: usb_f_mass_storage usb_f_hid usb_f_acm u_serial btsdio bluetooth ecdh_generic ecc brcmfmac brcmutil cfg80211 raspberrypi_hwmon hwmon i2c_mux_pinctrl i2c_mux bcm2835_unicam i2c_bcm2835 iproc_rng200 rng_core bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common rpivid_mem uio_pdrv_genirq uio sch_fq_codel snd_bcm2835(C) snd_pcm snd_timer snd tc358743 v4l2_dv_timings v4l2_fwnode videodev mc cec libcomposite dwc2 udc_core drm drm_panel_orientation_quirks ip_tables x_tables ipv6 nf_defrag_ipv6
[   79.766074] CPU: 3 PID: 34 Comm: kworker/3:1 Tainted: G         C        5.4.35-1-ARCH #1
[   79.774292] Hardware name: BCM2711
[   79.777717] Workqueue: events dbs_work_handler
[   79.782192] [<c0211424>] (unwind_backtrace) from [<c020c6fc>] (show_stack+0x10/0x14)
[   79.789977] [<c020c6fc>] (show_stack) from [<c0ccc638>] (dump_stack+0x94/0xb4)
[   79.806238] [<c0ccc638>] (dump_stack) from [<c022ceb8>] (__warn+0xd0/0xf8)
[   79.817766] [<c022ceb8>] (__warn) from [<c022d29c>] (warn_slowpath_fmt+0x98/0xc4)
[   79.834301] [<c022d29c>] (warn_slowpath_fmt) from [<c0b36468>] (rpi_firmware_transaction+0xe8/0x124)
[   79.852463] [<c0b36468>] (rpi_firmware_transaction) from [<c0b36550>] (rpi_firmware_property_list+0xac/0x168)
[   79.871582] [<c0b36550>] (rpi_firmware_property_list) from [<c0b3666c>] (rpi_firmware_property+0x60/0x108)
[   79.890551] [<c0b3666c>] (rpi_firmware_property) from [<c0928494>] (raspberrypi_clock_property+0x48/0x78)
[   79.909488] [<c0928494>] (raspberrypi_clock_property) from [<c09285f8>] (raspberrypi_fw_set_rate+0x44/0xb8)
[   79.928821] [<c09285f8>] (raspberrypi_fw_set_rate) from [<c0921c94>] (clk_change_rate+0xe0/0x558)
[   79.947361] [<c0921c94>] (clk_change_rate) from [<c0922284>] (clk_core_set_rate_nolock+0x178/0x1a0)
[   79.966220] [<c0922284>] (clk_core_set_rate_nolock) from [<c09222dc>] (clk_set_rate+0x30/0x88)
[   79.984877] [<c09222dc>] (clk_set_rate) from [<c0b03da8>] (dev_pm_opp_set_rate+0x364/0x460)
[   80.003253] [<c0b03da8>] (dev_pm_opp_set_rate) from [<c0b0d0bc>] (set_target+0x2c/0x54)
[   80.021370] [<c0b0d0bc>] (set_target) from [<c0b07e08>] (__cpufreq_driver_target+0x220/0x534)
[   80.040342] [<c0b07e08>] (__cpufreq_driver_target) from [<c0b0b32c>] (od_dbs_update+0xb4/0x160)
[   80.059658] [<c0b0b32c>] (od_dbs_update) from [<c0b0c4c4>] (dbs_work_handler+0x2c/0x58)
[   80.078284] [<c0b0c4c4>] (dbs_work_handler) from [<c02489ec>] (process_one_work+0x1f0/0x588)
[   80.097449] [<c02489ec>] (process_one_work) from [<c0248dd0>] (worker_thread+0x4c/0x528)
[   80.116348] [<c0248dd0>] (worker_thread) from [<c024ec28>] (kthread+0x128/0x154)
[   80.134600] [<c024ec28>] (kthread) from [<c02010d8>] (ret_from_fork+0x14/0x3c)
[   80.152846] Exception stack(0xef2a9fb0 to 0xef2a9ff8)
[   80.163429] 9fa0:                                     00000000 00000000 00000000 00000000
[   80.182818] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[   80.202646] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[   80.215376] ---[ end trace 91bfd0c131224965 ]---
[   80.226095] raspberrypi-clk firmware-clocks: Failed to change pllb frequency: -110
[   80.718577] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   80.730213] tc358743 10-000f: i2c_rd: reading register 0x2 from 0xf failed
[   81.758599] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   81.770193] tc358743 10-000f: i2c_wr: writing register 0x2 from 0xf failed
[   82.798624] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   82.810166] tc358743 10-000f: i2c_wr: writing register 0x2 from 0xf failed
[   83.838648] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   83.850108] tc358743 10-000f: i2c_wr: writing register 0x14c from 0xf failed
[   84.878670] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   84.890186] tc358743 10-000f: i2c_wr: writing register 0x150 from 0xf failed
[   85.918697] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   85.930211] tc358743 10-000f: i2c_wr: writing register 0x210 from 0xf failed
[   86.958710] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   86.970186] tc358743 10-000f: i2c_wr: writing register 0x214 from 0xf failed
[   87.998734] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   88.010264] tc358743 10-000f: i2c_wr: writing register 0x218 from 0xf failed
[   89.038749] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   89.050252] tc358743 10-000f: i2c_wr: writing register 0x21c from 0xf failed
[   90.078765] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   90.090261] tc358743 10-000f: i2c_wr: writing register 0x220 from 0xf failed
[   91.118779] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   91.130418] tc358743 10-000f: i2c_wr: writing register 0x224 from 0xf failed
[   92.158791] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   92.170372] tc358743 10-000f: i2c_wr: writing register 0x228 from 0xf failed
[   93.198809] i2c-bcm2835 fe205000.i2c: i2c transfer timed out
[   93.210184] tc358743 10-000f: i2c_wr: writing register 0x22c from 0xf failed

To reproduce Set up Auvidea B101 with kernel 4.4.35, run any capture software that supports DV-timings (https://github.com/pikvm/ustreamer, yavta, etc) and stop it.

Expected behaviour No crashes when closing the device file

Actual behaviour Subj

System

Logs Attached kernel log from tty. Just I2C errors: log1.txt

MMC crash: log2.txt

mdevaev commented 4 years ago

@6by9 I'm sorry to call you directly, but you may be interested in this issue. However, I'm not sure if this is related to the tc358743 driver, because somehow it affected the MMC card driver as well. If you need more logs, I will try to provide them to you as soon as possible.

6by9 commented 4 years ago

Please provide your full configuration from config.txt.

5.4 has reworked i2c-0 to use the i2c-mux-pinctrl module to switch it between GPIOs 0&1, and whichever GPIOs the display/camera connector are attached to (either 28&29, or 44&45 dependent on variant). Any userspace messing with pinmuxing for i2c-0 should be avoided. i2c-0 is always GPIOs 0&1. i2c-10 is the camera/display.

We've also had a fairly significant update to the bcm2835-unicam driver as part of the work for libcamera, but that seems sound.

I'll have a look to see if there is anything obvious using standard v4l2-ctl commands.

MMC and the firmware blocked warnings generally mean you've managed to kill the firmware, typically a memory trample somehow.

6by9 commented 4 years ago

It looks like my B101 board has died - it is recognised fine, set EDID and timings fine, but it doesn't produce any output data with either 5.4.38 or 4.19.118. I'll see if I can get a B102 working on a CM as I don't think I have another B101 around.

6by9 commented 4 years ago

OK, working fine with v4l2-ctl and yavta on a CM3L with B102, with kernel 5.4.35 and firmware 688a8f8f3d84e788f07f53c93693e1705f68c407 (rpi-update 8d64ec70 - top of tree today). Source is 720p60 from a Pi3. Works in either RGB3 or UYVY.

More information required, particularly the source resolution and frame rate, format chosen from the B101, and what processing you're doing.

I have a suspicion that it may be a firmware change that is the problem, not the kernel. There were a few changes to the video_encoder and ISP components relatively recently. Can you do rpi-update to get the latest kernel and firmware, and then sudo SKIP_KERNEL=1 rpi-update e5d3320 to revert the firmware to that hash (28 Feb in this case). If that works, work forward in commits to https://github.com/Hexxeh/rpi-firmware/commits/master until it fails.

mdevaev commented 4 years ago

config.txt:

initramfs initramfs-linux.img followkernel

hdmi_force_hotplug=1
gpu_mem=256
start_x=1
enable_uart=1
dtoverlay=tc358743
dtoverlay=pi3-disable-bt
dtoverlay=dwc2
dtparam=i2c_arm=on

The last line does not affect the presence of the problem, I added it out of desperation when trying to understand what is happening. If you delete it, the problem persists.

More information required, particularly the source resolution and frame rate, format chosen from the B101, and what processing you're doing.

I tried to simplify the way to reproduce the problem. The initial info about the launch of two times in a row, quite correct, the error appears upon termination of the read stream. I used yavta with EDID from your repository. Tried 720p/60Hz and 1080p/60Hz with UYVY - both resulted in a hang when pressing Ctrl+C.

./yavta --capture=1000 -n 3 --encode-to=file.h264 -f UYVY -m -T /dev/video0
...
Ctrl+C
// Kernel crash

It looks like my B101 board has died - it is recognised fine, set EDID and timings fine, but it doesn't produce any output data with either 5.4.38 or 4.19.118.

By the way. This is not relevant, but as my users have found out, the B101 may burn due to an accidentally flown CSI cable.

Both 4.x and 5.x kernels used firmware 688a8f8. I am using Arch Linux and using rpi-update will completely break the system. So I installed minimal Raspbian and used same config.txt exclude initramfs and i2c_arm lines. I also updated the system and executed rpi-update 8d64ec70. The problem was successfully reproduced wih yavta:

pi@raspberrypi:~ $ vcgencmd version
May  1 2020 17:56:42
Copyright (c) 2012 Broadcom
version 688a8f8f3d84e788f07f53c93693e1705f68c407 (clean) (release) (start_x)
pi@raspberrypi:~ $ uname -a
Linux raspberrypi 5.4.35-v7l+ #1314 SMP Fri May 1 17:47:34 BST 2020 armv7l GNU/Linux

Then I started moving through the firmware versions, as you said.

pi@raspberrypi:~ $ sudo SKIP_KERNEL=1 rpi-update e5d3320
<reboot>
pi@raspberrypi:~ $ uname -a
Linux raspberrypi 5.4.35-v7l+ #1314 SMP Fri May 1 17:47:34 BST 2020 armv7l GNU/Linux
pi@raspberrypi:~ $ vcgencmd version
Feb 28 2020 18:45:36
Copyright (c) 2012 Broadcom
version 9520663ed4fa4ca8c2a6923a522bff85fcdedef5 (clean) (release) (start_x)

The problem was successfully reproduced again.

I assume you failed to reproduce it because you used CM3, not RPi4. Perhaps the model of the video capture board has some significance (but they seem to differ slightly from each other).

6by9 commented 4 years ago

1080p60 can't be supported using a B101.

The B101 and B102 only differ in the number of CSI2 lanes that they present on the output connector, and the physical connector itself. CM3 vs Pi4 have very few differences in the hardware blocks involved here. We're using the Unicam driver heavily for the recent libcamera work, so know that is sound over multiple runs.

I currently have no way to reproduce, so can't actually help. Things to try (all after having provided an EDID):

mdevaev commented 4 years ago

1080p60 can't be supported using a B101.

Sorry, probably the KDE dialog is deceiving me and we are talking about 50 Hz. I forgot about this feature.

CM3 vs Pi4 have very few differences in the hardware blocks involved here.

I found a 3B+ board and tried. The problem is not reproduced on it even without --encode-to=file.h264. I believe that the problem is still directly related to RPi4.

provide the output from raspigpio get after the first run of yavta, and again after the second run has failed to start streaming (ideally when the second run is progress too).

I can't. I made a mistake in the initial diagnostics; immediately when the yavta process is interrupted, the core becomes inoperable.

drop out the --encode-to=file.h264 from yavta. If that works then it points to an issue with H264 encode.

Reproduced.

v4l2-ctl --stream-mmap=3 --stream-to=/dev/null --stream-count=1000 It doesn't do anything, just returns New timings found. Are some parameters missing?

rpi-update e1050e9482

Not reproduced.


Given the fact that I also tested on RPi 3B+ and the problem did not reproduce there, it seems that the problem is reproduced exactly and only on 5.4 and RPi4. The problem exists on two different B101 boards and several RPi4 users I contacted.

What else could I do to help you debug this?

6by9 commented 4 years ago

You can try adding core_freq_min=250 to /boot/config.txt, although I'd expect that to impact both kernel versions.

v4l2-ctl --stream-mmap=3 --stream-to=/dev/null --stream-count=1000 should print out a '>' for every frame received, and print an fps value each second.

You've got me fairly stumped if rpi-update e1050e9482 (4.19) works but 8d64ec7 (5.4) doesn't, and only on a Pi4.

I'll have a dig through my parts boxes to see if I have another B101. Unfortunately there isn't a way to attach a B102 to a standard Pi - the 15pin to 22pin adapters are not reversible. The FFC cable on the one that was working is fairly kinked, so if nothing else I can try swapping the cables. It'd be nice to know what the cause of the failure was, but probably just static onto the CSI lines (shame it's that sensitive).

6by9 commented 4 years ago

@pelwell Any thoughts as to any setup that has changed only on Pi4 between 4.19 and 5.4 that would trip I2C this up? We have got Maxime's updated clock driver, but that applies to both Pi3 and Pi4.

pelwell commented 4 years ago

Any thoughts as to any setup that has changed only on Pi4 between 4.19 and 5.4 that would trip I2C this up?

There's nothing specific to Pi 4 that I'm aware of that only affects I2C. It's probably worth making sure the EEPROM is up-to-date:

$ sudo rpi-eeprom-update
mdevaev commented 4 years ago

@6by9

You can try adding core_freq_min=250 to /boot/config.txt, although I'd expect that to impact both kernel versions.

Made with both kernels. It didn't affect anything.

@pelwell

BCM2711 detected
BOOTLOADER: up-to-date
CURRENT: Thu 16 Apr 17:11:26 UTC 2020 (1587057086)
 LATEST: Thu 16 Apr 17:11:26 UTC 2020 (1587057086)
 FW DIR: /lib/firmware/raspberrypi/bootloader/critical
VL805: up-to-date
CURRENT: 000137ad
 LATEST: 000137ad
pelwell commented 4 years ago

There are a lot of under-voltage warnings in your "i2c" log above. Either you are using a bad power supply or you are trying to power too much from your Pi.

The Pi 4 includes under-voltage detection logic because there is a real possibility your Pi will malfunction in some way or other. Every silicon die is unique in its analogue electrical properties, causing the voltage tolerance to vary between devices, but as you reduce the voltage gradually eventually the weakest link in the chain will break. If you're lucky, one of the ARM cores will panic immediately, but the failure could be memory corruption that has time to propagate and perhaps even make it to persistent storage.

You won't get support here until the under-voltage is resolved - it's not in your best interests.

mdevaev commented 4 years ago

(Sorry for the deleted message, I attached the wrong log)

@pelwell Okay, good point. I changed the power supply to a more powerful one and again successfully reproduced the problem, but this time without a single report of power problems.

The terminal log is attached. Messages may differ slightly from launch to launch (as I've shown before), but it always starts with I2C messages.

screenlog.txt

mdevaev commented 4 years ago

I understand that the problem looks strange. But it really exists not only for me, but for five other users that I know. All of them updated the kernel to 5.4 on RPi4 and all of them started having problems with B101 by I2C.

I have excluded all previous assumptions about the nature of this bug. How else can I help fix it?

pelwell commented 4 years ago

I'm starting to think that I2C is just collateral damage caused by a firmware lockup.

Your original reports says "an attempt to get an image from the tc358743 device twice in a row (reopen device file) results [in] I2C timeouts." Let's see if we can narrow down the cause of the failure by breaking the process down into a sequence of smaller steps.

  1. Disable the initial loading of the driver by commenting out the dtoverlay line in config.txt.
  2. Boot the Pi and use i2cdetect, i2cget, etc. to see if I2C seems to be working.
  3. Apply the overlay manually from the command line - "sudo dtoverlay tc358743".
  4. More i2cdetect, i2cget, etc.
  5. Try to get one image from the device.
  6. i2cdetect.
  7. Try to get another image from the device.
  8. i2cdetect.
mdevaev commented 4 years ago

The first message was not entirely accurate, I wrote. The problem does not occur on the second start, but when the first reading process is interrupted. That is, I run yavta, press Ctrl+C and immediately got a dead kernel. I played around with yavta a bit and found out that the problem occurs either when closing /dev/video0 or when executing ioctl VIDIOC_STREAMOFF. I think the tc358743 driver is trying to command something over I2C, and everything stops working.

So I tried to follow your instructions:

  1. Done.
  2. I didn't see any i2c devices in /dev and added in i2c_arm=on in config.txt. After that, I saw the i2c-1, but there were no devices in it. If I don't disable the overlay, I can execute and get the following:
    pi@raspberrypi:~ $ i2cdetect -y 10
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
    00:          -- -- -- -- -- -- -- -- -- -- -- -- UU
    10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
    20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
    30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
    40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
    50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
    60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
    70: -- -- -- -- -- -- -- --
    pi@raspberrypi:~ $ dmesg | grep tc3
    [    6.492908] tc358743 10-000f: tc358743 found @ 0x1e (i2c-11-mux (chan_id 1))
    pi@raspberrypi:~ $ sudo i2cget 10 0x1e
    WARNING! This program can confuse your I2C bus, cause data loss and worse!
    I will read from device file /dev/i2c-10, chip address 0x1e, current data
    address, using read byte.
    Continue? [Y/n]
    Error: Read failed
  3. Disabling the overlay and trying to load it manually:
    pi@raspberrypi:~ $ sudo dtoverlay tc358743
    * Failed to apply overlay '0_tc358743' (kernel)
    pi@raspberrypi:~ $ dmesg | tail -n 20
    ... // Nothing related
    [   93.592265] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c0mux/i2c@1/status
    [   93.592364] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/csi@7e801000/status
    [   93.592388] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/csi@7e801000/port/endpoint/remote-endpoint
    [   93.592448] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c@7e205000/status
    [   93.592466] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c0mux/status
    [   93.592490] OF: overlay: ERROR: multiple fragments add and/or delete node /soc/i2c0mux/i2c@1/tc358743@0f
    [   93.592631] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /soc/i2c0mux/i2c@1/tc358743@0f/name
    [   93.592724] OF: overlay: ERROR: multiple fragments add and/or delete node /soc/i2c0mux/i2c@1/tc358743@0f/port
    [   93.592742] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /soc/i2c0mux/i2c@1/tc358743@0f/port/name
    [   93.592763] OF: overlay: ERROR: multiple fragments add and/or delete node /soc/i2c0mux/i2c@1/tc358743@0f/port/endpoint
    [   93.593019] OF: overlay: ERROR: multiple fragments add, update, and/or delete property /soc/i2c0mux/i2c@1/tc358743@0f/port/endpoint/name
pelwell commented 4 years ago

The errors in 3 suggest that you have failed to disable the overlay in config.txt. You can verify that the overlay isn't present by looking in /proc/device-tree/soc/i2c0mux/i2c@1.

6by9 commented 4 years ago

You'll need dtparam=i2c_vc=on as we're looking for the camera/display i2c, not the one on GPIOs 2&3. Addr 0x0f showing up as UU also denotes that there is a kernel driver already loaded and using that address, which stops userspace access (unless you add a force flag - -f in i2cget).

mdevaev commented 4 years ago

@pelwell I clarified that. The driver is not loaded and the overlay is missing:

pi@raspberrypi:~ $ cat /boot/config.txt
hdmi_force_hotplug=1
gpu_mem=256
start_x=1
enable_uart=1
#dtoverlay=tc358743
dtoverlay=pi3-disable-bt
#dtoverlay=dwc2
#core_freq_min=250
#dtparam=i2c_arm=on
pi@raspberrypi:~ $ dmesg | grep tc3
pi@raspberrypi:~ $ ls /proc/device-tree/soc/i2c0mux/i2c@1
'#address-cells'   name   phandle   reg  '#size-cells'
pi@raspberrypi:~ $ find /proc/device-tree/soc/i2c0mux/
/proc/device-tree/soc/i2c0mux/
/proc/device-tree/soc/i2c0mux/i2c@0
/proc/device-tree/soc/i2c0mux/i2c@0/#address-cells
/proc/device-tree/soc/i2c0mux/i2c@0/#size-cells
/proc/device-tree/soc/i2c0mux/i2c@0/phandle
/proc/device-tree/soc/i2c0mux/i2c@0/reg
/proc/device-tree/soc/i2c0mux/i2c@0/name
/proc/device-tree/soc/i2c0mux/compatible
/proc/device-tree/soc/i2c0mux/pinctrl-1
/proc/device-tree/soc/i2c0mux/status
/proc/device-tree/soc/i2c0mux/i2c@1
/proc/device-tree/soc/i2c0mux/i2c@1/#address-cells
/proc/device-tree/soc/i2c0mux/i2c@1/#size-cells
/proc/device-tree/soc/i2c0mux/i2c@1/phandle
/proc/device-tree/soc/i2c0mux/i2c@1/reg
/proc/device-tree/soc/i2c0mux/i2c@1/name
/proc/device-tree/soc/i2c0mux/#address-cells
/proc/device-tree/soc/i2c0mux/i2c-parent
/proc/device-tree/soc/i2c0mux/#size-cells
/proc/device-tree/soc/i2c0mux/phandle
/proc/device-tree/soc/i2c0mux/pinctrl-0
/proc/device-tree/soc/i2c0mux/name
/proc/device-tree/soc/i2c0mux/pinctrl-names
pi@raspberrypi:~ $
pelwell commented 4 years ago

You're right - the overlay was written in a time when overlays modifying their own fragments was a bad idea, for which there is a workaround with an unfortunate side effect where you can't apply the overlay at runtime. You should be on a recent firmware with a 5.4 kernel, so I'll tweak the overlay to make it work in both scenarios.

mdevaev commented 4 years ago

@6by9 Thanks! Correct me if I'm doing something wrong. I have never worked with I2C.

pi@raspberrypi:~ $ cat /boot/config.txt 
hdmi_force_hotplug=1
gpu_mem=256
start_x=1
enable_uart=1
#dtoverlay=tc358743
dtoverlay=pi3-disable-bt
dtparam=i2c_vc=on
#dtoverlay=dwc2
#core_freq_min=250
#dtparam=i2c_arm=on
pi@raspberrypi:~ $ ls /dev/i2c-*
/dev/i2c-0  /dev/i2c-10  /dev/i2c-11
pi@raspberrypi:~ $ i2cdetect -y 0
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- --
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --
pi@raspberrypi:~ $ i2cdetect -y 10
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- 0f
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --
pi@raspberrypi:~ $ i2cdetect -y 11
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- 0f
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --
pi@raspberrypi:~ $ dmesg | grep tc3
mdevaev commented 4 years ago

@pelwell I didn't quite understand - are you going to make some kind of fix now and I will need to download it via rpi-update? Or is something else required of me?

pelwell commented 4 years ago

Can you test this updated overlay for me? It applies for me without any errors:

// SPDX-License-Identifier: GPL-2.0-only
// Definitions for Toshiba TC358743 HDMI to CSI2 bridge on VC I2C bus
/dts-v1/;
/plugin/;

/{
    compatible = "brcm,bcm2835";

    fragment@0 {
        target = <&i2c_csi_dsi>;
        __overlay__ {
            #address-cells = <1>;
            #size-cells = <0>;
            status = "okay";

            tc358743@0f {
                compatible = "toshiba,tc358743";
                reg = <0x0f>;
                status = "okay";

                clocks = <&tc358743_clk>;
                clock-names = "refclk";

                tc358743_clk: bridge-clk {
                    compatible = "fixed-clock";
                    #clock-cells = <0>;
                    clock-frequency = <27000000>;
                };

                port {
                    tc358743: endpoint {
                        remote-endpoint = <&csi1_ep>;
                        clock-lanes = <0>;
                        clock-noncontinuous;
                        link-frequencies =
                            /bits/ 64 <486000000>;
                    };
                };
            };
        };
    };

    fragment@1 {
        target = <&csi1>;
        __overlay__ {
            status = "okay";

            port {
                csi1_ep: endpoint {
                    remote-endpoint = <&tc358743>;
                };
            };
        };
    };

    fragment@2 {
        target = <&tc358743>;
        __overlay__ {
            data-lanes = <1 2>;
        };
    };

    fragment@3 {
        target = <&tc358743>;
        __dormant__ {
            data-lanes = <1 2 3 4>;
        };
    };

    fragment@4 {
        target = <&i2c0if>;
        __overlay__ {
            status = "okay";
        };
    };

    fragment@5 {
        target = <&i2c0mux>;
        __overlay__ {
            status = "okay";
        };
    };

    __overrides__ {
        4lane = <0>, "-2+3";
        link-frequency = <&tc358743>,"link-frequencies#0";
    };
};
mdevaev commented 4 years ago

@pelwell Sure. How do I do this?

pelwell commented 4 years ago

Save the code to a file - tc358743-overlay.dts is the usual name. Then run:

$ dtc -@ -I dts -O dtb -o tc358743.dtbo tc358743-overlay.dts
$ sudo cp tc358743.dtbo /boot/overlays
6by9 commented 4 years ago

/dev/i2c-0 is GPIOs 0&1 (pins 28&29) /dev/i2c-10 is the camera/display I2C /dev/i2c-11 is an anomally, and is whichever of the above was last selected :-/

pi@raspberrypi:~ $ dmesg | grep tc3
[    6.492908] tc358743 10-000f: tc358743 found @ 0x1e (i2c-11-mux (chan_id 1))

would imply that you did still have the overlay loaded from config.txt, but we're beyond that now.

pelwell commented 4 years ago

[ corrected typo in the cp line above ]

mdevaev commented 4 years ago

@6by9 I have only pi3-disable-bt to access to UART. The rest is disabled, it can be seen from config.txt. I don't know where it came from.

@pelwell Okay give me 5 minutes.

pelwell commented 4 years ago

Use sudo vcdbg log msg to read diagnostic messages from the firmware - you should see overlays being processed (or not).

6by9 commented 4 years ago

Use sudo vcdbg log msg to read diagnostic messages from the firmware - you should see overlays being processed (or not).

Doesn't that need dtdebug=1 in config.txt to show up overlay stuff?

pelwell commented 4 years ago

You will get more info that way, but the basic yes/no is there from the file accesses.

pelwell commented 4 years ago

e.g.

004510.857: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xb4ac
004587.307: brfs: File read: 46252 bytes
004599.989: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
005060.356: brfs: File read: 1371 bytes
005062.675: brfs: File read: /mfs/sd/config.txt
005062.760: dtparam: audio=on
005154.713: brfs: File read: 269 bytes
005167.340: brfs: File read: /mfs/sd/overlays/vc4-fkms-v3d.dtbo
005305.932: Loaded overlay 'vc4-fkms-v3d'
005656.871: brfs: File read: 1238 bytes
005659.221: brfs: File read: /mfs/sd/cmdline.txt
005659.373: Read command line from file 'cmdline.txt':
005659.463: 'zswap.zpool=zbud xearlycon=uart8250,mmio32,0xfe215040 console=serial0,115200 console=tty1 root=PARTUUID=ea7d04d6-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait plymouth.ignore-serial-consoles loglevel=8'
007400.053: brfs: File read: 218 bytes
007900.456: brfs: File read: /mfs/sd/kernel7l.img
007900.493: Loading 'kernel7l.img' to 0x8000 size 0x5b1628
007900.540: Device tree loaded to 0x2eff4500 (size 0xba75)
mdevaev commented 4 years ago

I don't know if it's important:

pi@raspberrypi:~ $ dtc -@ -I dts -O dtb -o tc358743.dtbo tc358743-overlay.dts
tc358743.dtbo: Warning (unit_address_vs_reg): /fragment@3: node has a unit name, but no reg property
tc358743.dtbo: Warning (unit_address_format): /fragment@0/__overlay__/tc358743@0f: unit name should not have leading 0s

Test 1: dtoverlay enabled in config.txt The video device has appeared, everything looks as usual. The problem persists. Also log:

pi@raspberrypi:~$ sudo vcdbg log msg
002905.214: arasan: arasan_emmc_open
002905.395: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000e7187 emmc: 250000000 actual: 200000 div: 0x00000271 target: 200000 min: 100000 max: 400000 delay: 10
003010.156: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000e7187 emmc: 250000000 actual: 200000 div: 0x00000271 target: 200000 min: 100000 max: 400000 delay: 10
003010.315: arasan: arasan_emmc_set_clock C0: 0x00000f00 C1: 0x000ec2c7 emmc: 250000000 actual: 129937 div: 0x000003c2 target: 130000 min: 100000 max: 400000 delay: 15
003065.069: arasan: arasan_emmc_set_clock C0: 0x00000f06 C1: 0x000e0307 emmc: 250000000 actual: 41666666 div: 0x00000003 target: 40000000 min: 0 max: 40000000 delay: 1
003336.362: brfs: File read: /mfs/sd/config.txt
003729.286: brfs: File read: 175 bytes
003755.583: brfs: File read: /mfs/sd/config.txt
004818.382: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
004820.853: *** Restart logging
004820.891: brfs: File read: 175 bytes
004834.033: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
004834.078: HDMI0: hdmi_pixel_encoding: 300000000

004834.090: HDMI1: hdmi_pixel_encoding: 300000000

004847.151: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
004847.190: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xb494
004921.359: brfs: File read: 46228 bytes
004940.560: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
005388.771: brfs: File read: 1371 bytes
005393.997: brfs: File read: /mfs/sd/config.txt
005394.885: brfs: File read: 175 bytes
005409.107: brfs: File read: /mfs/sd/overlays/tc358743.dtbo
005520.570: Loaded overlay 'tc358743'
005853.887: dtwarn: overlay 'pi3-disable-bt' has been renamed 'disable-bt'
005854.627: brfs: File read: 2071 bytes
005861.742: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo
005962.834: Loaded overlay 'pi3-disable-bt'
006241.088: brfs: File read: 954 bytes
006246.055: brfs: File read: /mfs/sd/cmdline.txt
006246.172: Read command line from file 'cmdline.txt':
006246.245: 'console=ttyAMA0,115200 console=tty1 root=PARTUUID=738a4d67-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait cma=128M'
008139.703: brfs: File read: 130 bytes
009313.353: brfs: File read: /mfs/sd/kernel7l.img
009313.439: Loading 'kernel7l.img' to 0x8000 size 0x5b1ce0
009313.527: Device tree loaded to 0x2eff4500 (size 0xba38)
009314.266: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
011073.242: vchiq_core: vchiq_init_state: slot_zero = 0xe6d80000, is_master = 1
011076.615: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
011083.469: TV service:host side not connected, dropping notification 0x00000002, 0x00000002, 0x00000004
015382.209: camsubs: Ignoring camera 0 as unicam device not available

Test 2: manual dtoverlay

[   79.904868] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c0mux/i2c@1/status
[   79.916570] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/csi@7e801000/status
[   79.928013] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/csi@7e801000/port/endpoint/remote-endpoint
[   79.941549] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c@7e205000/status
[   79.953121] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c0mux/status
[   79.980701] i2c i2c-11: Added multiplexed i2c bus 0
[   79.987784] i2c i2c-11: Added multiplexed i2c bus 10
002903.685: arasan: arasan_emmc_open
002903.866: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000e7187 emmc: 250000000 actual: 200000 div: 0x00000271 target: 200000 min: 100000 max: 400000 delay: 10
003008.626: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000e7187 emmc: 250000000 actual: 200000 div: 0x00000271 target: 200000 min: 100000 max: 400000 delay: 10
003008.785: arasan: arasan_emmc_set_clock C0: 0x00000f00 C1: 0x000ec2c7 emmc: 250000000 actual: 129937 div: 0x000003c2 target: 130000 min: 100000 max: 400000 delay: 15
003063.354: arasan: arasan_emmc_set_clock C0: 0x00000f06 C1: 0x000e0307 emmc: 250000000 actual: 41666666 div: 0x00000003 target: 40000000 min: 0 max: 40000000 delay: 1
003334.717: brfs: File read: /mfs/sd/config.txt
003727.635: brfs: File read: 176 bytes
003753.931: brfs: File read: /mfs/sd/config.txt
004816.725: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
004819.196: *** Restart logging
004819.234: brfs: File read: 176 bytes
004832.380: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
004832.426: HDMI0: hdmi_pixel_encoding: 300000000

004832.438: HDMI1: hdmi_pixel_encoding: 300000000

004845.496: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
004845.534: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xb494
004919.767: brfs: File read: 46228 bytes
004938.994: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
005387.191: brfs: File read: 1371 bytes
005392.550: brfs: File read: /mfs/sd/config.txt
005392.988: dtwarn: overlay 'pi3-disable-bt' has been renamed 'disable-bt'
005393.742: brfs: File read: 176 bytes
005397.717: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo
005497.973: Loaded overlay 'pi3-disable-bt'
005773.171: brfs: File read: 954 bytes
005778.156: brfs: File read: /mfs/sd/cmdline.txt
005778.279: Read command line from file 'cmdline.txt':
005778.360: 'console=ttyAMA0,115200 console=tty1 root=PARTUUID=738a4d67-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait cma=128M'
007663.137: brfs: File read: 130 bytes
008856.027: brfs: File read: /mfs/sd/kernel7l.img
008856.106: Loading 'kernel7l.img' to 0x8000 size 0x5b1ce0
008856.204: Device tree loaded to 0x2eff4700 (size 0xb86f)
008856.948: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
010625.001: vchiq_core: vchiq_init_state: slot_zero = 0xe6d80000, is_master = 1
010628.448: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
010635.271: TV service:host side not connected, dropping notification 0x00000002, 0x00000002, 0x00000004
014915.139: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015215.947: camsubs: Camera not found
015216.042: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015516.839: camsubs: Camera not found
015516.932: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015517.716: camsubs: Camera not found
015517.808: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015518.592: camsubs: Camera not found
015518.683: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015519.278: camsubs: Camera found OK
pi@raspberrypi:~ $ i2cdetect -y 0
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- --
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --
pi@raspberrypi:~ $ i2cdetect -y 10
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- 0f
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --
pi@raspberrypi:~ $ i2cdetect -y 11
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- 0f
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --
pi@raspberrypi:~ $ dmesg | grep tc3
pi@raspberrypi:~ $ sudo i2cget -f 10 0x0f
WARNING! This program can confuse your I2C bus, cause data loss and worse!
I will read from device file /dev/i2c-10, chip address 0x0f, current data
address, using read byte.
Continue? [Y/n]
0x00

After that, I tried to load the tc358743 module, but nothing happened. There was no message about the video device in the dmesg.

pelwell commented 4 years ago

The dtc warning is annoying but expected.

005853.887: dtwarn: overlay 'pi3-disable-bt' has been renamed 'disable-bt'

This line tells you that pi3-disable-bt has been replaced by the more generic disable-bt. At some point in the future the old name will be removed.

The fact that you are getting the same results at runtime as with the firmware-applied overlay is good because it takes one variable out of the equation. It also suggests that the patched overlay is working.

mdevaev commented 4 years ago

This line tells you that pi3-disable-bt has been replaced by the more generic disable-bt. At some point in the future the old name will be removed.

I've used this on our embedded systems. It is good that you warned me about this, I will release a patch that will make the necessary correction to the device configs. Thanks!

It also suggests that the patched overlay is working.

Cool. Although everything else has not yet been applied-the tc358743 module loads, but does nothing after manually applying dtoverlay.

If necessary, I can provide you with remote access to our test subject's serial console. Well, if it helps in any way.

6by9 commented 4 years ago

This sounds remarkably familiar to an issue I was having trying to dynamically load imx477.dtbo. The clock appears not to get created, therefore we get -E_PROBE_DEFER repeatedly, and it never loads. I was going to ask @pelwell about it when it came back to the top of my list.

pelwell commented 4 years ago

It's because of the location of the clock node. Try this one:

// SPDX-License-Identifier: GPL-2.0-only
// Definitions for Toshiba TC358743 HDMI to CSI2 bridge on VC I2C bus
/dts-v1/;
/plugin/;

/{
    compatible = "brcm,bcm2835";

    fragment@0 {
        target = <&i2c_csi_dsi>;
        __overlay__ {
            #address-cells = <1>;
            #size-cells = <0>;
            status = "okay";

            tc358743@0f {
                compatible = "toshiba,tc358743";
                reg = <0x0f>;
                status = "okay";

                clocks = <&tc358743_clk>;
                clock-names = "refclk";

                port {
                    tc358743: endpoint {
                        remote-endpoint = <&csi1_ep>;
                        clock-lanes = <0>;
                        clock-noncontinuous;
                        link-frequencies =
                            /bits/ 64 <486000000>;
                    };
                };
            };
        };
    };

    fragment@1 {
        target = <&csi1>;
        __overlay__ {
            status = "okay";

            port {
                csi1_ep: endpoint {
                    remote-endpoint = <&tc358743>;
                };
            };
        };
    };

    fragment@2 {
        target = <&tc358743>;
        __overlay__ {
            data-lanes = <1 2>;
        };
    };

    fragment@3 {
        target = <&tc358743>;
        __dormant__ {
            data-lanes = <1 2 3 4>;
        };
    };

    fragment@4 {
        target = <&i2c0if>;
        __overlay__ {
            status = "okay";
        };
    };

    fragment@5 {
        target = <&i2c0mux>;
        __overlay__ {
            status = "okay";
        };
    };

    fragment@6 {
        target-path = "/";
        __overlay__ {
            tc358743_clk: bridge-clk {
                compatible = "fixed-clock";
                #clock-cells = <0>;
                clock-frequency = <27000000>;
            };
        };
    };

    __overrides__ {
        4lane = <0>, "-2+3";
        link-frequency = <&tc358743>,"link-frequencies#0";
    };
};

I'll explain more fully after lunch.

mdevaev commented 4 years ago
[   95.157695] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c0mux/i2c@1/status
[   95.168929] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/csi@7e801000/status
[   95.180039] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/csi@7e801000/port/endpoint/remote-endpoint
[   95.193234] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c@7e205000/status
[   95.204443] OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc/i2c0mux/status
[   95.241861] i2c i2c-11: Added multiplexed i2c bus 0
[   95.250502] i2c i2c-11: Added multiplexed i2c bus 10
[   95.299606] link-frequencies 0 value 486000000
[   95.382201] tc358743 10-000f: tc358743 found @ 0x1e (i2c-11-mux (chan_id 1))
002906.011: arasan: arasan_emmc_open
002906.192: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000e7187 emmc: 250000000 actual: 200000 div: 0x00000271 target: 200000 min: 100000 max: 400000 delay: 10
003010.953: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000e7187 emmc: 250000000 actual: 200000 div: 0x00000271 target: 200000 min: 100000 max: 400000 delay: 10
003011.112: arasan: arasan_emmc_set_clock C0: 0x00000f00 C1: 0x000ec2c7 emmc: 250000000 actual: 129937 div: 0x000003c2 target: 130000 min: 100000 max: 400000 delay: 15
003065.843: arasan: arasan_emmc_set_clock C0: 0x00000f06 C1: 0x000e0307 emmc: 250000000 actual: 41666666 div: 0x00000003 target: 40000000 min: 0 max: 40000000 delay: 1
003337.273: brfs: File read: /mfs/sd/config.txt
003730.192: brfs: File read: 172 bytes
003756.514: brfs: File read: /mfs/sd/config.txt
004819.307: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
004821.779: *** Restart logging
004821.817: brfs: File read: 172 bytes
004834.959: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
004835.004: HDMI0: hdmi_pixel_encoding: 300000000

004835.017: HDMI1: hdmi_pixel_encoding: 300000000

004848.091: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
004848.130: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xb494
004922.318: brfs: File read: 46228 bytes
004941.184: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
005389.254: brfs: File read: 1371 bytes
005394.628: brfs: File read: /mfs/sd/config.txt
005395.522: brfs: File read: 172 bytes
005399.510: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo
005499.780: Loaded overlay 'disable-bt'
005775.165: brfs: File read: 954 bytes
005780.130: brfs: File read: /mfs/sd/cmdline.txt
005780.253: Read command line from file 'cmdline.txt':
005780.334: 'console=ttyAMA0,115200 console=tty1 root=PARTUUID=738a4d67-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait cma=128M'
007663.754: brfs: File read: 130 bytes
008839.707: brfs: File read: /mfs/sd/kernel7l.img
008839.789: Loading 'kernel7l.img' to 0x8000 size 0x5b1ce0
008839.886: Device tree loaded to 0x2eff4700 (size 0xb86f)
008840.622: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
010608.229: vchiq_core: vchiq_init_state: slot_zero = 0xe6d80000, is_master = 1
010611.630: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
010618.477: TV service:host side not connected, dropping notification 0x00000002, 0x00000002, 0x00000004
015021.214: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015322.023: camsubs: Camera not found
015322.119: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015622.913: camsubs: Camera not found
015623.009: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015623.793: camsubs: Camera not found
015623.906: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015624.689: camsubs: Camera not found
015624.784: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
015625.380: camsubs: Camera found OK

Also:

pi@raspberrypi:~$ i2cdetect -y 10
     0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f
00:          -- -- -- -- -- -- -- -- -- -- -- -- UU
10: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
20: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
30: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
40: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
50: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
60: -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --
70: -- -- -- -- -- -- -- --

This time the module loaded and the device started working. However, the subj problem still persists.

pelwell commented 4 years ago

@6by9 Device nodes can't just be placed arbitrarily if we expect them to be recognised and cause kernel device objects to be instantiated. Children of buses are instantiated by their parents, as are all children of the root. Certain other compatible strings are searched for globally during kernel initialisation - "fixed-clock" is one of them - but this only works if the node is already present when the kernel boots; if it is added later anywhere other than on a bus (or in the root) it get ignored.

I'll look for other affected overlays - I know that the new imx477 overlay (https://github.com/raspberrypi/linux/pull/3605) is one of them.

6by9 commented 4 years ago

I hate magic stuff that you just have to know about :-(

All the CSI devices will be affected as they all had the same parentage tc358743, adv7282, ov5647, imx219, imx477, and irs1125. I thought I'd tried moving the clock to / and it hadn't worked. Perhaps I dropped it under the more logical /clk instead, which I guess then has the same issue.

pelwell commented 4 years ago

It's logical when you think about it - each bus needs to be able to look at its children to decide how and when to initialise them - but it's unfortunate that the fixed-clocks of this world muddy the waters.

mdevaev commented 4 years ago

My colleague (hw engineer) and I did another check. We checked the level on this pad (I2C SDA).

image

Before the video capture process, it was high. At the moment of hanging, it becomes permanently low, and keeps at this level until the B101 is reseted by connecting RESET and GND. After resetting, the SDA again shows a high level. My colleague's hypothesis is that the I2C state machine is hanging on waiting for NACK, possibly on both sides.

pelwell commented 4 years ago

At this point you could really benefit from a logic analyser, but you might get something useful from the kernels event tracing. Load the overlay in your preferred way, then before starting yavta run:

$ sudo sh -c "echo 1 >/sys/kernel/debug/tracing/events/i2c/enable"

Now run the capture, exiting with Ctrl-C in the usual way, and capture the trace events to a file:

$ sudo cp /sys/kernel/debug/tracing/trace trace_1.txt

N.B.: /sys/kernel/debug requires root privileges to access, so you won't get the usual command TAB-completion behaviour unless you are running as root.

Run this sequence 2 or 3 times (so we can verify that the trace ends the same way every time - or not), using a different output file name each time, and upload the results somewhere like pastebin, DropBox, Google Drive etc.

mdevaev commented 4 years ago

I was lucky. I managed to make two dumps. Usually the kernel breaks down so that even the serial terminal no longer works. The dumps turned out to be quite small. Each dump contains an EDID loading stage, getting five frames, and calling VIDIOC_STREAMOFF. I didn't perform a RESET.

In addition, I have attached another log of kernel messages.

trace_1.txt trace_2.txt screenlog.txt

In fact, I can go as far as using a logic analyzer, but this is currently problematic. But if there is no way out...

pelwell commented 4 years ago

Thanks - they're interesting logs, identical except for some minor timing effects.

The timeout occurs after a particular write to I2C register 0x0004, known to the driver as CONFCTL. Here is a list of all of them:

i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-14-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-14-0c]
i2c_result: i2c-11 n=1 ret=1
i2c_result: i2c-10 n=1 ret=1
--
i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-14-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-14-0c]
i2c_result: i2c-11 n=1 ret=1
i2c_result: i2c-10 n=1 ret=1
--
i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-14-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-14-0c]
i2c_result: i2c-11 n=1 ret=1
i2c_result: i2c-10 n=1 ret=1
--
i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [14-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-d4-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-d4-0c]
i2c_result: i2c-11 n=1 ret=1
i2c_result: i2c-10 n=1 ret=1
--
i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [d4-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [d4-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-d4-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-d4-0c]
i2c_result: i2c-11 n=1 ret=1
i2c_result: i2c-10 n=1 ret=1
--
i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [d4-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [d4-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-d7-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-d7-0c]
i2c_result: i2c-11 n=1 ret=1
i2c_result: i2c-10 n=1 ret=1
--
i2c_write: i2c-11 #0 a=00f f=0000 l=2 [00-04]
i2c_read: i2c-11 #1 a=00f f=0001 l=2
i2c_reply: i2c-11 #1 a=00f f=0001 l=2 [d7-0c]
i2c_result: i2c-11 n=2 ret=2
i2c_reply: i2c-10 #1 a=00f f=0001 l=2 [d7-0c]
i2c_result: i2c-10 n=2 ret=2
i2c_write: i2c-10 #0 a=00f f=0000 l=4 [00-04-d4-0c]
i2c_write: i2c-11 #0 a=00f f=0000 l=4 [00-04-d4-0c]
i2c_result: i2c-11 n=1 ret=-110
i2c_result: i2c-10 n=1 ret=-110

The addition of the mux duplicates all the activities, but it's still clear enough. The -110 is the timeout, of course.

Decoding this a bit further, the sequence of operations to CONFCTL is (again, from the driver):

read 0c14 -> write 0c14   # AUDCHNUM_2 | AUDOUTSEL_I2S | AUTOINDEX
read 0c14 -> write 0c14
read 0c14 -> write 0c14
read 0c14 -> write 0cd4   # Set YCBCRFMT_422_8_BIT
read 0cd4 -> write 0cd4
read 0cd4 -> write 0cd7   # Set ABUFEN & VBUFEN = enable_stream(true)
read 0cd7 -> write 0cd4   # Clear ABUFEN & VBUFEN = enable_stream(false)
[ timeout ]

I haven't been able to find a datasheet for the device, so my questions are:

  1. Are there restrictions on when ABUFEN and VBUFEN can be cleared?
  2. Does the device return NACK (or something) until some event has occurred such as a FIFO emptying?
  3. Might the driver shutdown order as the result of a Ctrl-C signal have changed?

I'd suggest adding a few tactical pr_err()s into enable_stream (showing the value of "enable") or even a WARN_ON(1), and other key points. Do something similar to the brcm_unicam driver as well.

6by9 commented 4 years ago

Just to keep you updated, the hunch is that there is something going wrong with the I2C mux.

pelwell is digging into the behaviour, whilst I'll try and sort a dtoverlay that disables it for you. It's all quite puzzling still.

mdevaev commented 4 years ago

Thanks! I really appreciate it.

6by9 commented 4 years ago

An alternate tc358743-overlay.dts to try

// SPDX-License-Identifier: GPL-2.0-only
// Definitions for Toshiba TC358743 HDMI to CSI2 bridge on VC I2C bus
/dts-v1/;
/plugin/;

/{
    compatible = "brcm,bcm2835";

    fragment@0 {
        target = <&i2c0if>;
        __overlay__ {
            #address-cells = <1>;
            #size-cells = <0>;
            status = "okay";

            tc358743@0f {
                compatible = "toshiba,tc358743";
                reg = <0x0f>;
                status = "okay";

                clocks = <&tc358743_clk>;
                clock-names = "refclk";

                port {
                    tc358743: endpoint {
                        remote-endpoint = <&csi1_ep>;
                        clock-lanes = <0>;
                        clock-noncontinuous;
                        link-frequencies =
                            /bits/ 64 <486000000>;
                    };
                };
            };
        };
    };

    fragment@1 {
        target = <&csi1>;
        __overlay__ {
            status = "okay";

            port {
                csi1_ep: endpoint {
                    remote-endpoint = <&tc358743>;
                };
            };
        };
    };

    fragment@2 {
        target = <&tc358743>;
        __overlay__ {
            data-lanes = <1 2>;
        };
    };

    fragment@3 {
        target = <&tc358743>;
        __dormant__ {
            data-lanes = <1 2 3 4>;
        };
    };

    fragment@4 {
        target = <&i2c0if>;
        __overlay__ {
            pinctrl-0 = <&i2c0_gpio44>;
            pinctrl-names = "default";
        };
    };

    fragment@5 {
        target-path = "/";
        __overlay__ {
            tc358743_clk: bridge-clk {
                compatible = "fixed-clock";
                #clock-cells = <0>;
                clock-frequency = <27000000>;
            };
        };
    };

    __overrides__ {
        4lane = <0>, "-2+3";
        link-frequency = <&tc358743>,"link-frequencies#0";
    };
};

and do NOT include dtparam=i2c_vc=on as it does cause grief (I've wasted a chunk of time on that one!) You should get just a /dev/i2c11, and that should be configured correctly for the camera connector on a Pi4 with no magic muxing.

mdevaev commented 4 years ago

Checked. The problem still remains, /dev/i2c-11 exists.

mdevaev commented 4 years ago

On the fourth attempt I was able to make traces. screenlog.txt trace.txt