Maximum I2C Clock Frequency

[Morten Nissov]

@Eric-Katzfey Also, we haven't added pullup-resistors ourselves. I'm not sure what kind of hardware already exists on the voxl 2 mini for this purpose. Cables are generally short though (<5cm) so I'm not sure how big of a deal this is.

[Eric Katzfey]

@Morten-Nissov It's quite possible that even though the code appears to support that rate it may not. Unfortunately, there really is no way for us to figure this out without being able to replicate your hardware setup. So when it crashes can you look at dmesg afterwards and see if you see a message indicating that Slpi has crashed? I'm assuming that you are using the i2c pins 4 and 5 on connector J19?

[Alex Kushleyev]

I did a quick test using existing i2c barometer driver (ICP101XX which is on board on VOXL2). The driver has default speed of 100khz : https://github.com/modalai/px4-firmware/blob/voxl-dev/src/drivers/barometer/invensense/icp101xx/Inven_Sense_ICP101XX_registers.hpp#L47 . I changed the speed to 400k and 1M and it works. Values above that (i tried 3M) causes the driver to fail to open port, specifically i can see the dsp output (using mini-dm) in case of failure :

[08500/01]  23:57.342  0047:01: SDSP: qshell gotten: icp101xx start -I -b 5  0088  qshell.cpp
[08500/01]  23:57.342  0047:01: SDSP:   arg0 = 'icp101xx'   0163  qshell.cpp
[08500/01]  23:57.342  0047:01: SDSP:   arg1 = 'start'   0163  qshell.cpp
[08500/01]  23:57.342  0047:01: SDSP:   arg2 = '-I'   0163  qshell.cpp
[08500/01]  23:57.342  0047:01: SDSP:   arg3 = '-b'   0163  qshell.cpp
[08500/01]  23:57.342  0047:01: SDSP:   arg4 = '5'   0163  qshell.cpp
[08500/01]  23:57.345  0045:01: SDSP: *** I2C Device ID 0xb76329 12018473  0072  I2C.cpp
[08500/02]  23:57.345  0045:01: SDSP: I2C Error: sns_scp_open failed  0885  sns_flight_controller_sensor_
[08500/03]  23:57.345  0045:01: SDSP: i2c init failed  0100  I2C.cpp

However, there is no crash even in case the port fails to open. At 1M speed, i am able to check module status using qshell icp101xx status and it does not report any bad transfers

I can stop and start the driver at run time without an issue.

You can test this out using the barometer driver yourself as well. I suspect there maybe some other issue that causes a crash. Also, you can unplug your mag and see if the issue remains at 1M speed setting (the expected behavior is that the i2c port should open but device won't be found, so driver won't start)

Alex

[Morten Nissov]

Sorry both for the delay, I've been out of office over easter.

@Eric-Katzfey We've tried the magnetometer + magnetometer library with 1MHz I2C on a teensy, so at least the non-voxl2 mini components should support it. Yes you're correct, about the pins. I'll take a look at the dmesg outputs tomorrow and get back to you.

@Alex-Kushleyev I'll try this as well: 1) starting driver at 1M w/out sensor to see driver starts and reports device not found, 2) starting driver manually during runtime and see status output.

Thanks for the support!

[Morten Nissov]

I set the I2C frequency to static constexpr uint32_t I2C_SPEED = 1000 * 1000; // 400 kHz I2C serial interface and flash the voxl2-mini. I then manually start px4 by voxl-px4 -d and wait until all is started. I then started the magnetometer driver by qshell tmag5273 start -X -b 1 which causes the px4 session to start printing a lot of messages and stop responding to things like ctrl+c:

pxh> qshell tmag5273 start -X -b 1
INFO  [qshell] Send cmd: 'tmag5273 start -X -b 1'
INFO  [muorb] SLPI: Marking DeviceNode(qshell_req) as advertised in process_remote_topic
INFO  [muorb] SLPI: qshell gotten: tmag5273 start -X -b 1
INFO  [muorb] SLPI:   arg0 = 'tmag5273'

INFO  [muorb] SLPI:   arg1 = 'start'

INFO  [muorb] SLPI:   arg2 = '-X'

INFO  [muorb] SLPI:   arg3 = '-b'

INFO  [muorb] SLPI:   arg4 = '1'

INFO  [muorb] SLPI: *** I2C Device ID 0xd3509 865545
INFO  [muorb] SLPI: Too many arming check events (1, 14 > 14). Not reporting all
INFO  [muorb] SLPI: Preflight Fail: Accel Sensor 0 missing
INFO  [muorb] SLPI: Preflight Fail: barometer 0 missing
INFO  [muorb] SLPI: Preflight Fail: ekf2 missing data
INFO  [muorb] SLPI: Preflight Fail: Gyro Sensor 0 missing
INFO  [muorb] SLPI: Preflight Fail: Compass Sensor 0 missing
INFO  [muorb] SLPI: Preflight Fail: Battery unhealthy
>>> Got an exception from send_request <<<
>>> Got an exception from send_request <<<
>>> Send failed after retries <<<
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Sending topic message
--- msg_id: 1033
--- topic name: telemetry_status
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Sending topic message
--- msg_id: 1033
--- topic name: telemetry_status
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Connection error: connection reset
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Got response cb 0
Got flight controller event
Received standard error event SNS_STD_ERROR_NOT_SUPPORTED
Sending topic message
--- msg_id: 1033
--- topic name: cpuload
Got response cb 0
Got flight controller event
Received standard error event SNS_STD_ERROR_NOT_SUPPORTED
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Got response cb 0
Got flight controller event
Received standard error event SNS_STD_ERROR_NOT_SUPPORTED
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode
Got response cb 0
Got flight controller event
Received standard error event SNS_STD_ERROR_NOT_SUPPORTED

The dmesg output seems too long, I'm not entirely sure what exactly I'm looking for but this piece at the end seemed interesting:

[    5.610560] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.615800] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.617899] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.618780] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.621479] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.622003] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.622899] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.622989] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.623637] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.624191] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.624915] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.626410] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.629129] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.631157] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.633089] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.633682] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.633727] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.641154] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.642545] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.645431] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.649037] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.649964] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.653350] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.660602] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.661748] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.670667] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.670926] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.671126] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.677110] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.679867] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.679921] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.680361] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.681618] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.681731] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.682135] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.682902] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.683738] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.683871] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.683900] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.684928] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.686749] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.687598] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.688077] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.689980] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.691480] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.692511] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.692563] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.692698] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.694912] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.695387] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.695556] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.697739] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.698446] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.698871] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.699012] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.701161] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.702005] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.704599] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.705506] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    5.706275] ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
[    6.202818] spi_geni 98c000.spi: tx_fifo 16 rx_fifo 16 tx_width 32
[    6.300368] Started adbd. 
[    7.122898] devfreq-qcom-fw 18590000.qcom,devfreq-l3:qcom,cdsp-cdsp-l3-lat: Successfully started CDSP L3 governor
[    7.615569] CAM_ERR: CAM-MEM: cam_mem_mgr_create_debug_fs: 126 failed to create dentry
[    7.645673] CAM_INFO: CAM-HFI: cam_hfi_init: 878 Init IO1 : [0x10c00000 0xcf300000] IO2 [0xe0200000 0x1ed00000]
[    7.655955] CAM_INFO: CAM-ICP: cam_icp_mgr_hw_open: 3879 FW download done successfully
[    7.655962] CAM_INFO: CAM-ICP: cam_icp_mgr_process_dbg_buf: 2572 FW_DBG:CICP_FW_E : HFI  :QC_IMAGE_VERSION_STRING=CICP.FW.1.0-00079,OEM_IMAGE_VERSION_STRING=CRM,BUILD_TIME: Oct 17 2019 05:49:19,CACHE_ENABLED at icphostinterface.c:636 QC_IMAGE_VERSION_STRING=CICP.FW.1.0-00079 OEM_IMAGE_VERSION_STRING=CRM
[    7.655968] CAM_INFO: CAM-ICP: cam_icp_mgr_process_dbg_buf: 2572 FW_DBG:CICP_FW_E : HFI  :ELF variant: CACHE-ENABLED:T480:API_V2:USE_CDM_1_1: , API version: 0x2000049 at icphostinterface.c:637 QC_IMAGE_VERSION_STRING=CICP.FW.1.0-00079 OEM_IMAGE_VERSION_STRING=CRM
[    7.826104] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Linked as a consumer to regulator.60
[    7.826159] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Linked as a consumer to regulator.79
[    7.849942] CAM_ERR: CAM-CCI: cam_cci_irq: 238 Base:        pK-error, M0_Q1 NACK ERROR: 0x10000000
[    7.850128] CAM_ERR: CAM-CCI: cam_cci_read: 1329 ERROR with Slave 0x7a:
[    7.850139] CAM_ERR: CAM-CCI: cam_cci_read_bytes: 1613 failed to read rc:-22
[    7.850147] CAM_ERR: CAM-SENSOR: cam_cci_i2c_read: 35 rc = -22
[    7.850158] CAM_WARN: CAM-SENSOR: cam_sensor_match_id: 707 read id: 0x0 expected id 0x3d:
[    7.850328] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Dropping the link to regulator.79
[    7.854323] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Dropping the link to regulator.60
[    7.883924] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Linked as a consumer to regulator.60
[    7.884305] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Linked as a consumer to regulator.79
[    7.901272] CAM_ERR: CAM-CCI: cam_cci_irq: 238 Base:        pK-error, M0_Q1 NACK ERROR: 0x10000000
[    7.901342] CAM_ERR: CAM-CCI: cam_cci_read: 1329 ERROR with Slave 0x20:
[    7.901351] CAM_ERR: CAM-CCI: cam_cci_read_bytes: 1613 failed to read rc:-22
[    7.901358] CAM_ERR: CAM-SENSOR: cam_cci_i2c_read: 35 rc = -22
[    7.901367] CAM_WARN: CAM-SENSOR: cam_sensor_match_id: 707 read id: 0x0 expected id 0x214:
[    7.901521] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Dropping the link to regulator.79
[    7.905194] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Dropping the link to regulator.60
[    7.933390] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Linked as a consumer to regulator.55
[    7.935713] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Linked as a consumer to regulator.60
[    7.935848] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Linked as a consumer to regulator.79
[    7.959966] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 731 [Applying Alternative Address] : Sensor Index   : 1464402100
[    7.959977] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 732 [Applying Alternative Address] : Slave Address  : 0xE2
[    7.959985] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 733 [Applying Alternative Address] : Slave sensor id: 0x7750
[    7.959993] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 734 [Applying Alternative Address] : cci_client sid : 0x71
[    7.960434] CAM_ERR: CAM-CCI: cam_cci_irq: 258 Base:        pK-error, M1_Q0 NACK ERROR: 0x20000000
[    7.960506] CAM_ERR: CAM-CCI: cam_cci_wait: 270 failed rc -22
[    7.960515] CAM_ERR: CAM-CCI: cam_cci_transfer_end: 345 failed rc -22
[    7.960526] CAM_ERR: CAM-CCI: cam_cci_data_queue: 870 Slave: 0xe0 failed rc -22
[    7.960533] CAM_ERR: CAM-CCI: cam_cci_i2c_write: 1450 failed rc: -22
[    7.960542] CAM_ERR: CAM-SENSOR: cam_cci_i2c_write_table_cmd: 123 Failed rc = -22
[    7.960550] CAM_ERR: CAM-SENSOR: cam_sensor_set_alt_id: 768 [Applying Alternative Address] : Probe : camera_io_dev_write failed: rc=-22
[    7.960701] CAM_ERR: CAM-CCI: cam_cci_irq: 264 Base:        pK-error, M1_Q1 NACK ERROR: 0x40000000
[    7.960766] CAM_ERR: CAM-CCI: cam_cci_read: 1329 ERROR with Slave 0xe0:
[    7.960774] CAM_ERR: CAM-CCI: cam_cci_read_bytes: 1613 failed to read rc:-22
[    7.960781] CAM_ERR: CAM-SENSOR: cam_cci_i2c_read: 35 rc = -22
[    7.960789] CAM_WARN: CAM-SENSOR: cam_sensor_match_id: 707 read id: 0x0 expected id 0x7750:
[    7.960912] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Dropping the link to regulator.79
[    7.964320] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Dropping the link to regulator.60
[    7.964463] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Dropping the link to regulator.55
[    8.017749] CAM_WARN: CAM-CRM: cam_req_mgr_close: 160 release invoked associated userspace process has died
[   10.386107] CAM_ERR: CAM-MEM: cam_mem_mgr_create_debug_fs: 126 failed to create dentry
[   10.401487] CAM_INFO: CAM-HFI: cam_hfi_init: 878 Init IO1 : [0x10c00000 0xcf300000] IO2 [0xe0200000 0x1ed00000]
[   10.412099] CAM_INFO: CAM-ICP: cam_icp_mgr_hw_open: 3879 FW download done successfully
[   10.412119] CAM_INFO: CAM-ICP: cam_icp_mgr_process_dbg_buf: 2572 FW_DBG:CICP_FW_E : HFI  :QC_IMAGE_VERSION_STRING=CICP.FW.1.0-00079,OEM_IMAGE_VERSION_STRING=CRM,BUILD_TIME: Oct 17 2019 05:49:19,CACHE_ENABLED at icphostinterface.c:636 QC_IMAGE_VERSION_STRING=CICP.FW.1.0-00079 OEM_IMAGE_VERSION_STRING=CRM
[   10.412130] CAM_INFO: CAM-ICP: cam_icp_mgr_process_dbg_buf: 2572 FW_DBG:CICP_FW_E : HFI  :ELF variant: CACHE-ENABLED:T480:API_V2:USE_CDM_1_1: , API version: 0x2000049 at icphostinterface.c:637 QC_IMAGE_VERSION_STRING=CICP.FW.1.0-00079 OEM_IMAGE_VERSION_STRING=CRM
[   10.481289] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Linked as a consumer to regulator.60
[   10.481326] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Linked as a consumer to regulator.79
[   10.504189] CAM_ERR: CAM-CCI: cam_cci_irq: 238 Base:        pK-error, M0_Q1 NACK ERROR: 0x10000000
[   10.504359] CAM_ERR: CAM-CCI: cam_cci_read: 1329 ERROR with Slave 0x7a:
[   10.504366] CAM_ERR: CAM-CCI: cam_cci_read_bytes: 1613 failed to read rc:-22
[   10.504370] CAM_ERR: CAM-SENSOR: cam_cci_i2c_read: 35 rc = -22
[   10.504374] CAM_WARN: CAM-SENSOR: cam_sensor_match_id: 707 read id: 0x0 expected id 0x3d:
[   10.504462] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Dropping the link to regulator.79
[   10.508103] qcom,camera ac4f000.qcom,cci:qcom,cam-sensor0: Dropping the link to regulator.60
[   10.534478] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Linked as a consumer to regulator.60
[   10.534525] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Linked as a consumer to regulator.79
[   10.550529] CAM_ERR: CAM-CCI: cam_cci_irq: 238 Base:        pK-error, M0_Q1 NACK ERROR: 0x10000000
[   10.550681] CAM_ERR: CAM-CCI: cam_cci_read: 1329 ERROR with Slave 0x20:
[   10.550686] CAM_ERR: CAM-CCI: cam_cci_read_bytes: 1613 failed to read rc:-22
[   10.550688] CAM_ERR: CAM-SENSOR: cam_cci_i2c_read: 35 rc = -22
[   10.550691] CAM_WARN: CAM-SENSOR: cam_sensor_match_id: 707 read id: 0x0 expected id 0x214:
[   10.550759] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Dropping the link to regulator.79
[   10.554106] qcom,camera ac50000.qcom,cci:qcom,cam-sensor2: Dropping the link to regulator.60
[   10.581531] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Linked as a consumer to regulator.55
[   10.584273] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Linked as a consumer to regulator.60
[   10.584486] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Linked as a consumer to regulator.79
[   10.609377] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 731 [Applying Alternative Address] : Sensor Index   : 1464402100
[   10.609388] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 732 [Applying Alternative Address] : Slave Address  : 0xE2
[   10.609396] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 733 [Applying Alternative Address] : Slave sensor id: 0x7750
[   10.609404] CAM_INFO: CAM-SENSOR: cam_sensor_set_alt_id: 734 [Applying Alternative Address] : cci_client sid : 0x71
[   10.609591] CAM_ERR: CAM-CCI: cam_cci_irq: 258 Base:        pK-error, M1_Q0 NACK ERROR: 0x20000000
[   10.609649] CAM_ERR: CAM-CCI: cam_cci_wait: 270 failed rc -22
[   10.609658] CAM_ERR: CAM-CCI: cam_cci_transfer_end: 345 failed rc -22
[   10.609668] CAM_ERR: CAM-CCI: cam_cci_data_queue: 870 Slave: 0xe0 failed rc -22
[   10.609677] CAM_ERR: CAM-CCI: cam_cci_i2c_write: 1450 failed rc: -22
[   10.609686] CAM_ERR: CAM-SENSOR: cam_cci_i2c_write_table_cmd: 123 Failed rc = -22
[   10.609695] CAM_ERR: CAM-SENSOR: cam_sensor_set_alt_id: 768 [Applying Alternative Address] : Probe : camera_io_dev_write failed: rc=-22
[   10.609780] CAM_ERR: CAM-CCI: cam_cci_read: 1340 read_words = 0, exp words = 1
[   10.609789] CAM_ERR: CAM-CCI: cam_cci_read_bytes: 1613 failed to read rc:-22
[   10.609807] CAM_ERR: CAM-SENSOR: cam_cci_i2c_read: 35 rc = -22
[   10.609828] CAM_WARN: CAM-SENSOR: cam_sensor_match_id: 707 read id: 0x0 expected id 0x7750:
[   10.609850] CAM_ERR: CAM-CCI: cam_cci_irq: 264 Base:        pK-error, M1_Q1 NACK ERROR: 0x40000000
[   10.610038] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Dropping the link to regulator.79
[   10.614302] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Dropping the link to regulator.60
[   10.614426] qcom,camera ac50000.qcom,cci:qcom,cam-sensor3: Dropping the link to regulator.55
[   10.667487] CAM_WARN: CAM-CRM: cam_req_mgr_close: 160 release invoked associated userspace process has died
[   16.001681] msm-usb-ssphy-qmp 88e8000.ssphy: USB DP QMP PHY: Update TYPEC CTRL(3)
[   16.056809] msm-dwc3 a600000.ssusb: DWC3 exited from low power mode
[   16.588523] android_work: sent uevent USB_STATE=CONNECTED
[   16.595024] android_work: sent uevent USB_STATE=DISCONNECTED
[   16.708577] android_work: sent uevent USB_STATE=CONNECTED
[   16.719299] configfs-gadget gadget: high-speed config #1: c
[   16.720248] android_work: sent uevent USB_STATE=CONFIGURED
[   33.761075] vdd_tof: disabling
[   33.761082] vdd_hap_boost: disabling
[  101.427770] boot log copy done
[  386.820967] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x41b08
[  493.337423] Fatal error on slpi!
[  493.337495] slpi subsystem failure reason: err_qdi.c:1063:PC=b21d30bc,SP=317b8a48,FP=317b8a78,LR=b21d300c,BADVA=96,CAUSE=7003,TASK=Anonymous.
[  493.337517] subsys-restart: subsystem_restart_dev(): Restart sequence requested for slpi, restart_level = RELATED.
[  493.338559] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is restarting
[  493.338564] subsys-restart: subsystem_shutdown(): [kworker/u19:0:1832]: Shutting down slpi
[  493.350877] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30030
[  493.350922] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30040
[  493.354910] coresight-remote-etm soc:ssc_etm0: Connection disconnected between QMI handle and 8 service
[  493.354939] sysmon-qmi: ssctl_del_server: Connection lost between QMI handle and slpi's SSCTL service
[  493.355792] adsprpc: fastrpc_rpmsg_remove: closed rpmsg channel of slpi
[  493.357015] adsprpc: fastrpc_restart_notifier_cb: received RAMDUMP notification for slpi
[  493.358631] subsys-restart: subsystem_powerup(): [kworker/u19:0:1832]: Powering up slpi
[  493.359427] subsys-pil-tz 5c00000.qcom,ssc: slpi: loading from 0x0000000088c00000 to 0x000000008a600000
[  493.424824] subsys-pil-tz 5c00000.qcom,ssc: slpi: Brought out of reset
[  493.481943] subsys-pil-tz 5c00000.qcom,ssc: Subsystem error monitoring/handling services are up
[  493.481967] subsys-pil-tz 5c00000.qcom,ssc: slpi: Power/Clock ready interrupt received
[  493.485644] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is up
[  493.485650] subsys-restart: subsystem_restart_wq_func(): [kworker/u19:0:1832]: Restart sequence for slpi completed.
[  493.486551] 724585192:Entered
[  493.487029] 724585192:SMD QRTR driver probed
[  493.491727] adsprpc: fastrpc_rpmsg_probe: opened rpmsg channel for slpi
[  493.496270] sysmon-qmi: ssctl_new_server: Connection established between QMI handle and slpi's SSCTL service
[  493.496274] coresight-remote-etm soc:ssc_etm0: Connection established between QMI handle and 8 service
[  493.500386] diag: In diag_send_peripheral_buffering_mode, buffering flag not set for 3
[  511.812370] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x41b08
[  511.812390] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x41b08
[  543.813331] Fatal error on slpi!
[  543.813445] slpi subsystem failure reason: err_qdi.c:1063:EF:sensor_process:0x1:Anonymous:0x3f:sns_com_port_i2c.c:239:status != I2C_ERROR_TRANSFER_TIMEOUT.
[  543.813505] subsys-restart: subsystem_restart_dev(): Restart sequence requested for slpi, restart_level = RELATED.
[  543.816229] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is restarting
[  543.816239] subsys-restart: subsystem_shutdown(): [kworker/u19:0:1832]: Shutting down slpi
[  543.830145] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30030
[  543.830185] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30040
[  543.830198] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30040
[  543.832708] adsprpc: fastrpc_rpmsg_remove: closed rpmsg channel of slpi
[  543.833188] adsprpc: fastrpc_restart_notifier_cb: received RAMDUMP notification for slpi
[  543.834471] coresight-remote-etm soc:ssc_etm0: Connection disconnected between QMI handle and 8 service
[  543.834596] sysmon-qmi: ssctl_del_server: Connection lost between QMI handle and slpi's SSCTL service
[  543.834722] subsys-restart: subsystem_powerup(): [kworker/u19:0:1832]: Powering up slpi
[  543.835597] subsys-pil-tz 5c00000.qcom,ssc: slpi: loading from 0x0000000088c00000 to 0x000000008a600000
[  543.900964] subsys-pil-tz 5c00000.qcom,ssc: slpi: Brought out of reset
[  543.962375] subsys-pil-tz 5c00000.qcom,ssc: Subsystem error monitoring/handling services are up
[  543.962598] subsys-pil-tz 5c00000.qcom,ssc: slpi: Power/Clock ready interrupt received
[  543.966771] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is up
[  543.966785] subsys-restart: subsystem_restart_wq_func(): [kworker/u19:0:1832]: Restart sequence for slpi completed.
[  543.967361] 724585192:Entered
[  543.967859] 724585192:SMD QRTR driver probed
[  543.972003] adsprpc: fastrpc_rpmsg_probe: opened rpmsg channel for slpi
[  543.986270] sysmon-qmi: ssctl_new_server: Connection established between QMI handle and slpi's SSCTL service
[  543.986299] coresight-remote-etm soc:ssc_etm0: Connection established between QMI handle and 8 service
[  543.987828] diag: In diag_send_peripheral_buffering_mode, buffering flag not set for 3
[  545.281536] Fatal error on slpi!
[  545.281639] slpi subsystem failure reason: err_qdi.c:1063:EF:sensor_process:0x1:SNS_SEE_I_1:0x68:sns_stream_service.c:436:req_found.
[  545.281693] subsys-restart: subsystem_restart_dev(): Restart sequence requested for slpi, restart_level = RELATED.
[  545.282937] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is restarting
[  545.282951] subsys-restart: subsystem_shutdown(): [kworker/u19:0:1832]: Shutting down slpi
[  545.296247] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30030
[  545.296267] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30030
[  545.296342] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30040
[  545.299310] coresight-remote-etm soc:ssc_etm0: Connection disconnected between QMI handle and 8 service
[  545.299396] adsprpc: fastrpc_rpmsg_remove: closed rpmsg channel of slpi
[  545.299877] sysmon-qmi: ssctl_del_server: Connection lost between QMI handle and slpi's SSCTL service
[  545.300918] adsprpc: fastrpc_restart_notifier_cb: received RAMDUMP notification for slpi
[  545.302334] subsys-restart: subsystem_powerup(): [kworker/u19:0:1832]: Powering up slpi
[  545.302732] subsys-pil-tz 5c00000.qcom,ssc: slpi: loading from 0x0000000088c00000 to 0x000000008a600000
[  545.376922] subsys-pil-tz 5c00000.qcom,ssc: slpi: Brought out of reset
[  545.438467] subsys-pil-tz 5c00000.qcom,ssc: Subsystem error monitoring/handling services are up
[  545.438529] subsys-pil-tz 5c00000.qcom,ssc: slpi: Power/Clock ready interrupt received
[  545.442768] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is up
[  545.442783] subsys-restart: subsystem_restart_wq_func(): [kworker/u19:0:1832]: Restart sequence for slpi completed.
[  545.443409] 724585192:Entered
[  545.443972] 724585192:SMD QRTR driver probed
[  545.449760] adsprpc: fastrpc_rpmsg_probe: opened rpmsg channel for slpi
[  545.451027] sysmon-qmi: ssctl_new_server: Connection established between QMI handle and slpi's SSCTL service
[  545.451059] coresight-remote-etm soc:ssc_etm0: Connection established between QMI handle and 8 service
[  545.459198] diag: In diag_send_peripheral_buffering_mode, buffering flag not set for 3
[  546.775564] Fatal error on slpi!
[  546.775671] slpi subsystem failure reason: err_qdi.c:1063:EF:sensor_process:0x1:SNS_SEE_I_0:0x69:sns_stream_service.c:436:req_found.
[  546.775730] subsys-restart: subsystem_restart_dev(): Restart sequence requested for slpi, restart_level = RELATED.
[  546.777007] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is restarting
[  546.777020] subsys-restart: subsystem_shutdown(): [kworker/u19:0:1832]: Shutting down slpi
[  546.790351] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30030
[  546.793366] adsprpc: fastrpc_rpmsg_remove: closed rpmsg channel of slpi
[  546.793908] coresight-remote-etm soc:ssc_etm0: Connection disconnected between QMI handle and 8 service
[  546.794365] sysmon-qmi: ssctl_del_server: Connection lost between QMI handle and slpi's SSCTL service
[  546.794985] adsprpc: fastrpc_restart_notifier_cb: received RAMDUMP notification for slpi
[  546.798133] subsys-restart: subsystem_powerup(): [kworker/u19:0:1832]: Powering up slpi
[  546.798436] subsys-pil-tz 5c00000.qcom,ssc: slpi: loading from 0x0000000088c00000 to 0x000000008a600000
[  546.878630] subsys-pil-tz 5c00000.qcom,ssc: slpi: Brought out of reset
[  546.941273] subsys-pil-tz 5c00000.qcom,ssc: Subsystem error monitoring/handling services are up
[  546.941338] subsys-pil-tz 5c00000.qcom,ssc: slpi: Power/Clock ready interrupt received
[  546.941470] qcom_rpmh DRV:apps_rsc TCS Busy, retrying RPMH message send: addr=0x30040
[  546.943459] adsprpc: fastrpc_restart_notifier_cb: slpi subsystem is up
[  546.943465] subsys-restart: subsystem_restart_wq_func(): [kworker/u19:0:1832]: Restart sequence for slpi completed.
[  546.943741] 724585192:Entered
[  546.944172] 724585192:SMD QRTR driver probed
[  546.945397] sysmon-qmi: ssctl_new_server: Connection established between QMI handle and slpi's SSCTL service
[  546.945412] coresight-remote-etm soc:ssc_etm0: Connection established between QMI handle and 8 service
[  546.949929] adsprpc: fastrpc_rpmsg_probe: opened rpmsg channel for slpi
[  546.955524] diag: In diag_send_peripheral_buffering_mode, buffering flag not set for 3

in particular the line [ 493.337495] slpi subsystem failure reason: err_qdi.c:1063:PC=b21d30bc,SP=317b8a48,FP=317b8a78,LR=b21d300c,BADVA=96,CAUSE=7003,TASK=Anonymous.

[Morten Nissov]

Hi again,

If it's of any help, the repo we're developing this on is: https://github.com/ntnu-arl/modalai-px4-firmware/tree/dev/tmag5273

There isn't really much going on aside from blending a sparkfun library into the ist8310 impl used as a px4 driver template.

[Eric Katzfey]

@Morten-Nissov Yes, that means the DSP running PX4 crashed

[Eric Katzfey]

@Morten-Nissov This line doesn't look good: ScheduleDelayed(1_us); That's too fast

[Morten Nissov]

@Eric-Katzfey I saw the shedule delayed call in the driver we used as template (with a different number), do you have a recommendation for what a lower bound should be?

We intentionally set it very low to gauge whether the I2C communication was limiting our update rate in the 400kHz case, which it was.

[Morten Nissov]

@Eric-Katzfey Hi again,

The same happens setting ScheduleDelayed to 20ms (even as high as 100ms). So I guess we're never getting to this point in the code before crashing.

Edit: The driver manages to run

	if (!strcmp(verb, "start")) {
		return ThisDriver::module_start(cli, iterator);
	}

however it never manages to enter void TMAG5273::RunImpl(). It seems like the crash happens at int ret = I2C::init(); in TMAG5273::init(). Using print statements I can see it never manages to execute any line which requires using I2C (e.g. reading a register for probing), which would seem to make sense is I2C never manages to startup.

Edit2: As per @Alex-Kushleyev message, I can also manage to change the barometer rate to 1MHz and it starts successfully:

INFO  [muorb] SLPI: qshell gotten: icp101xx start -I -b 5
INFO  [muorb] SLPI:   arg0 = 'icp101xx'

INFO  [muorb] SLPI:   arg1 = 'start'

INFO  [muorb] SLPI:   arg2 = '-I'

INFO  [muorb] SLPI:   arg3 = '-b'

INFO  [muorb] SLPI:   arg4 = '5'

INFO  [muorb] SLPI: *** I2C Device ID 0xb76329 12018473
INFO  [muorb] SLPI: icp101xx #0 on I2C bus 5
INFO  [muorb] SLPI:  address 0x63
INFO  [muorb] SLPI: 

INFO  [muorb] SLPI: Ok executing command: icp101xx start -I -b 5

As far as I can see there is virtually no difference in how our mag driver and the barometer driver initialize the I2C object. Note, unplugging the magnetometer results in the same crash as before

INFO  [muorb] SLPI: qshell gotten: tmag5273 start -X -b 1
INFO  [muorb] SLPI:   arg0 = 'tmag5273'

INFO  [muorb] SLPI:   arg1 = 'start'

INFO  [muorb] SLPI:   arg2 = '-X'

INFO  [muorb] SLPI:   arg3 = '-b'

INFO  [muorb] SLPI:   arg4 = '1'

INFO  [muorb] SLPI: -----------------------here-------------------
INFO  [muorb] SLPI: -----------------------hi-------------------
INFO  [muorb] SLPI: -----------------------start-------------------
INFO  [muorb] SLPI: *** I2C Device ID 0xd3509 865545
INFO  [muorb] SLPI: -------------------- const
INFO  [muorb] SLPI: -------------------- init
INFO  [muorb] SLPI: -------------------- probe
INFO  [muorb] SLPI: -------------------- isConnected
INFO  [muorb] SLPI: Too many arming check events (1, 14 > 14). Not reporting all
INFO  [muorb] SLPI: Preflight Fail: Accel Sensor 0 missing
INFO  [muorb] SLPI: Preflight Fail: barometer 0 missing
INFO  [muorb] SLPI: Preflight Fail: ekf2 missing data
INFO  [muorb] SLPI: Preflight Fail: Gyro Sensor 0 missing
INFO  [muorb] SLPI: Preflight Fail: Compass Sensor 0 missing
INFO  [muorb] SLPI: Preflight Fail: Battery unhealthy
>>> Got an exception from send_request <<<
>>> Send succeeded after retries <<<
Sending topic message
--- msg_id: 1033
--- topic name: offboard_control_mode

Note, this time there are some print statement I added to check where the crash was happening. As before it doesn't manage to get past int ret = I2C::init();.

[Alex Kushleyev]

@Morten-Nissov,

I am not sure exactly what the issue is with 1Mbit i2c rate, but i see another way how you can speed up your reads. Currently the code reads each of the 3 axes separately (X, Y and Z) and each axis is using two separate i2c calls to read the value (LSB and MSB). For each single byte read, it actually takes about 3 bytes (time-wise) because the first byte is the slave address, second byte is the address of register to read and 3rd byte is actual value sent by the sensor.

All the result registers are stored one after another, specifically designed to be read in a single batch : https://github.com/ntnu-arl/modalai-px4-firmware/blob/dev/tmag5273/src/drivers/magnetometer/tmag5273/TI_TMAG5273_registers.hpp#L187 . So you should change your code to make a single read to read all of the result registers, and if you use the current 400khz, you will get at least 3x speedup, at least in the reading part. Then you have to make sure the sensor has completed the conversion, or whatever is steps are needed for the sensor update cycle.

Alex

[Morten Nissov]

@Alex-Kushleyev Sorry if this is a stupid question, for reading more than one byte with the px4 I2C implementation we do this by calling transfer(&cmd, 1, &buffer, num_read); with the appropriate number for num_read, or is there more to do?

[Alex Kushleyev]

@Morten-Nissov

Yes you can read more than 1 byte at a time by setting num_read accordingly and making sure the buffer for holding the incoming data is large enough. You would need to set the read address to the start address where you want to start reading the data array.

Then you will need to parse the data out of the returned array into x, y, z axes (and temperature if you are reading that).

[Morten Nissov]

@Alex-Kushleyev Sorry didn't see the message, but ended up getting the same place. Implemented a read multiple registers which seems to work:

void TMAG5273::RegisterReadMultiple(Register reg, uint8_t* buffer, uint8_t bytes)
{
    const uint8_t cmd = static_cast<uint8_t>(reg);
    transfer(&cmd, 1, buffer, bytes);
}

This turned out to be significantly faster (~4x I think), so even without 1MHz I think it could be sufficient for us. Thanks for the help!

[Alex Kushleyev]

@Morten-Nissov , great! You are welcome. Make sure to change that 1us scheduling interval to a more reasonable value