Bug #118872
【OTA】【网络】86升级到95，95再升级最新版本（621DB版本），副屏网络不可用，中控网络正常
| Status: | CLOSED | Start date: | 2023-06-21 | |
|---|---|---|---|---|
| Priority: | High | Due date: | ||
| Assignee: | 物联网测试组_CDTS 唐霞 | % Done: | 100% | |
| Category: | SYSTEM | |||
| Target version: | - | |||
| Need_Info: | -- | Found Version: | 01.00.C105_20230621_private_user（621DB版本） | |
| Resolution: | FIXED | Degrated: | No | |
| Severity: | Major | Verified Version: | ||
| Reproducibility: | Rarely | Fixed Version: | 2023-06-30 | |
| Test Type: | DB-Check | Root cause: | 接受开机广播慢导致mcu超时 |
Description
【测试步骤】
1.QFIL刷机86版本
2.86版本本地OTA升级到95版本
3.95版本本地OTA升级到最新版本（621DB版本）
【预期结果】
升级到最新版本后，所有功能正常，可正常使用
【测试结果】
副屏网络不可用，中控网络正常；菜单栏没有显示以太网图标
History
#1 Updated by 物联网测试组_CDTS 唐霞 about 2 years ago
PassengerDisplay:/ $ getprop |grep network
getprop |grep network
[init.svc.neuralnetworks_hal_service]: [running]
[ro.telephony.default_network]: [33,33]
[sys.network.wifi]: [1]
PassengerDisplay:/ $ ip route
ip route
default via 192.168.4.4 dev vlan4 linkdown
192.168.0.0/24 dev vlan0 proto kernel scope link src 192.168.0.16 linkdown
192.168.1.0/24 dev vlan1 proto kernel scope link src 192.168.1.16 linkdown
192.168.2.0/24 dev vlan2 proto kernel scope link src 192.168.2.16 linkdown
192.168.4.0/24 dev vlan4 proto kernel scope link src 192.168.4.16 linkdown
192.168.8.0/24 dev vlan8 proto kernel scope link src 192.168.8.16 linkdown
192.168.11.0/24 dev vlan11 proto kernel scope link src 192.168.11.16 linkdown
192.168.124.0/24 dev wlan0 proto kernel scope link src 192.168.124.19
PassengerDisplay:/ $ ifconfig
ifconfig
wlan0 Link encap:UNSPEC Driver cnss_pci
inet addr:192.168.124.19 Bcast:192.168.124.255 Mask:255.255.255.0
inet6 addr: fe80::8445:c8ff:fe2e:d27c/64 Scope: Link
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:43246 errors:0 dropped:1 overruns:0 frame:0
TX packets:9475 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:3000
RX bytes:14772333 TX bytes:1817325
vlan0 Link encap:UNSPEC
inet addr:192.168.0.16 Bcast:192.168.0.255 Mask:255.255.255.0
inet6 addr: fe80::347c:7cff:fe00:f/64 Scope: Link
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:75 errors:0 dropped:0 overruns:0 frame:0
TX packets:253 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:3150 TX bytes:23144
vlan11 Link encap:UNSPEC
inet addr:192.168.11.16 Bcast:192.168.11.255 Mask:255.255.255.0
inet6 addr: fe80::347c:7cff:fe00:f/64 Scope: Link
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:0 errors:0 dropped:0 overruns:0 frame:0
TX packets:174 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:0 TX bytes:18830
eth0 Link encap:UNSPEC Driver lan743x
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:4294967295 errors:4294967291 dropped:4294967295 overruns:0 frame:0
TX packets:4294967295 errors:4294967293 dropped:4294967295 overruns:0 carrier:0
collisions:4294967293 txqueuelen:1000
RX bytes:4294967293 TX bytes:4294967293
vlan4 Link encap:UNSPEC
inet addr:192.168.4.16 Bcast:192.168.4.255 Mask:255.255.255.0
inet6 addr: fe80::347c:7cff:fe00:f/64 Scope: Link
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:4069 errors:0 dropped:0 overruns:0 frame:0
TX packets:4436 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:1703904 TX bytes:656815
dummy0 Link encap:UNSPEC
inet6 addr: fe80::b896:11ff:fe9d:e3b6/64 Scope: Link
UP BROADCAST RUNNING NOARP MTU:1500 Metric:1
RX packets:0 errors:0 dropped:0 overruns:0 frame:0
TX packets:104 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:0 TX bytes:14344
vlan1 Link encap:UNSPEC
inet addr:192.168.1.16 Bcast:192.168.1.255 Mask:255.255.255.0
inet6 addr: fe80::347c:7cff:fe00:f/64 Scope: Link
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:0 errors:0 dropped:0 overruns:0 frame:0
TX packets:192 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:0 TX bytes:20342
vlan8 Link encap:UNSPEC
inet addr:192.168.8.16 Bcast:192.168.8.255 Mask:255.255.255.0
inet6 addr: fe80::347c:7cff:fe00:f/64 Scope: Link
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:0 errors:0 dropped:0 overruns:0 frame:0
TX packets:176 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:0 TX bytes:19074
lo Link encap:UNSPEC
inet addr:127.0.0.1 Mask:255.0.0.0
inet6 addr: ::1/128 Scope: Host
UP LOOPBACK RUNNING MTU:65536 Metric:1
RX packets:101822 errors:0 dropped:0 overruns:0 frame:0
TX packets:101822 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:10029490 TX bytes:10029490
vlan2 Link encap:UNSPEC
inet addr:192.168.2.16 Bcast:192.168.2.255 Mask:255.255.255.0
inet6 addr: fe80::347c:7cff:fe00:f/64 Scope: Link
UP BROADCAST MULTICAST MTU:1504 Metric:1
RX packets:0 errors:0 dropped:0 overruns:0 frame:0
TX packets:188 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:0 TX bytes:19890
#2 Updated by 物联网测试组_CDTS 唐霞 about 2 years ago
#3 Updated by CD TPM-王祥林 about 2 years ago
- Assignee changed from CD TPM-王祥林 to CD_BSP 彭文亮
出问题的开机次数是168次。下电后重新上电网络就正常了。
#4 Updated by CD TPM-王祥林 about 2 years ago
- Category set to BSP
#7 Updated by CD_BSP 彭文亮 about 2 years ago
经过日志分析
1）第一个发现是
不但有线网络不正常工作，mcu也在不正常的工作
01-01 08:00:30.288 0 0 I [ 27.616061] mv2112_setup_work_handler: Try to setup link again! #采用的是临门一脚的方式，因为该MCU来发起信号，确没有等来。
01-01 08:00:30.288 0 0 I : [ 27.616065] mv2112_setup_forced
01-01 08:00:30.925 0 0 E [ 28.256316] mv2112_update_link: link 0x4
01-01 08:00:30.925 0 0 I : [ 28.256328] lan743x 0001:01:00.0 eth0: Link is Up - 100Mbps/Full - flow control off
06-21 11:41:00.795 0 0 I : [ 108.032553] lan743x 0001:01:00.0 eth0: Link is Down #突然有线网络断连
06-21 11:41:07.794 0 0 I : [ 115.030810] mv2112_setup_forced #此时MCU突然发来信号，不应该收到。
06-21 11:41:07.794 0 0 I [ 115.030816] mv2112_setup_forced: Already setup link!
2）第二个发现
06-21 11:40:56.825 0 0 E [ 104.062712] msm_pcie_handle_linkdown: PCIe link is down for RC1 #有线网络mac控制器lan743x挂接在RC1上.RC1先停止，lan743x随后停止。
06-21 11:41:00.795 0 0 I : [ 108.032553] lan743x 0001:01:00.0 eth0: Link is Down
经过继续分析，为什么RC1 会 link down：
Event MSM_PCIE_EVENT_LINKDOWN
When the RC hardware detects an abnormal linkdown, an interrupt is generated. 从这句定义来看，是一个硬件发起的异常。
#8 Updated by CD_BSP 彭文亮 about 2 years ago
1）请mcu同事陈宙贤看过之后。认为mcu存在超时重启（mcu未收到MPU正常工作或者显示屏点亮的这一信号），由于mpu已经正常工作，所以后面mcu永远不会收到该信号，mcu会不断的超时重启。
2）需要祥林看一下，通信层，在dmesg25S时，为何不通；在mcu超时重启后，又通了。通信层，到底好久通的。@王祥林
#9 Updated by CD TPM-王祥林 about 2 years ago
正常情况下开机时间小于20s。出问题的时候开机时间明显过长，kernel启动完都用了17秒，42秒才进入Launcher。
MCU判断为15秒内没有完成开机就会认为超时了，重新对mpu上电和发送link up信号。
正常log：
/FSEM_000167_0207_0621113301/logcat/000167_persist_00057_700101_080009.log:01-01 08:00:08.376 680 680 I boot_progress_start: 5408
./FSEM_000167_0207_0621113301/logcat/000167_persist_00058_700101_080009.log:01-01 08:00:08.836 680 680 I boot_progress_preload_start: 5868
./FSEM_000167_0207_0621113301/logcat/000167_persist_00059_700101_080009.log:01-01 08:00:09.797 680 680 I boot_progress_preload_end: 6829
./FSEM_000167_0207_0621113301/logcat/000167_persist_00059_700101_080009.log:01-01 08:00:09.984 1519 1519 I boot_progress_system_run: 7016
./FSEM_000167_0207_0621113301/logcat/000167_persist_00059_700101_080009.log:01-01 08:00:10.494 1519 1519 I boot_progress_pms_start: 7526
./FSEM_000167_0207_0621113301/logcat/000167_persist_00060_700101_080010.log:01-01 08:00:10.646 1519 1519 I boot_progress_pms_system_scan_start: 7678
./FSEM_000167_0207_0621113301/logcat/000167_persist_00060_700101_080010.log:01-01 08:00:10.852 1519 1519 I boot_progress_pms_data_scan_start: 7884
./FSEM_000167_0207_0621113301/logcat/000167_persist_00060_700101_080010.log:01-01 08:00:11.688 1519 1519 I boot_progress_pms_scan_end: 8720
./FSEM_000167_0207_0621113301/logcat/000167_persist_00060_700101_080010.log:01-01 08:00:11.764 1519 1519 I boot_progress_pms_ready: 8796
./FSEM_000167_0207_0621113301/logcat/000167_persist_00061_230510_180123.log:05-10 18:01:23.805 1519 1519 I boot_progress_ams_ready: 9889
./FSEM_000167_0207_0621113301/logcat/000167_persist_00063_230621_113249.log:06-21 11:32:49.311 1519 1580 I boot_progress_enable_screen: 11131
./FSEM_000167_0207_0621113301/logcat/000167_persist_00063_230621_113249.log:06-21 11:32:50.358 1519 1580 I wm_boot_animation_done: 12178
异常log：
./FSEM_000168_0208_0621114129/logcat/000168_persist_00094_700101_080021.log:01-01 08:00:19.589 701 701 I boot_progress_start: 16920
./FSEM_000168_0208_0621114129/logcat/000168_persist_00095_700101_080021.log:01-01 08:00:20.106 701 701 I boot_progress_preload_start: 17437
./FSEM_000168_0208_0621114129/logcat/000168_persist_00096_700101_080021.log:01-01 08:00:21.125 701 701 I boot_progress_preload_end: 18456
./FSEM_000168_0208_0621114129/logcat/000168_persist_00096_700101_080021.log:01-01 08:00:21.419 1580 1580 I boot_progress_system_run: 18750
./FSEM_000168_0208_0621114129/logcat/000168_persist_00097_700101_080021.log:01-01 08:00:22.431 1580 1580 I boot_progress_pms_start: 19762
./FSEM_000168_0208_0621114129/logcat/000168_persist_00097_700101_080021.log:01-01 08:00:22.532 1580 1580 I boot_progress_pms_system_scan_start: 19863
./FSEM_000168_0208_0621114129/logcat/000168_persist_00097_700101_080021.log:01-01 08:00:23.801 1580 1580 I boot_progress_pms_data_scan_start: 21133
./FSEM_000168_0208_0621114129/logcat/000168_persist_00098_700101_080025.log:01-01 08:00:30.762 1580 1580 I boot_progress_pms_scan_end: 28093
./FSEM_000168_0208_0621114129/logcat/000168_persist_00098_700101_080025.log:01-01 08:00:30.994 1580 1580 I boot_progress_pms_ready: 28325
./FSEM_000168_0208_0621114129/logcat/000168_persist_00100_230621_055411.log:06-21 05:54:12.116 1580 1580 I boot_progress_ams_ready: 39786
./FSEM_000168_0208_0621114129/logcat/000168_persist_00103_230621_055413.log:06-21 05:54:13.627 1580 1661 I boot_progress_enable_screen: 41297
./FSEM_000168_0208_0621114129/logcat/000168_persist_00103_230621_055413.log:06-21 11:38:58.836 1580 1661 I wm_boot_animation_done: 42153
下一步：
1.需要调查一下启动慢的原因。
2.修改MCU的超时检查时间。
#10 Updated by CD_BSP 彭文亮 about 2 years ago
注：
通过让陈宙贤更改mcu的程序，发现mcu的超时重新上电时序是造成pcie1和 有线网络link is down的直接原因。
#11 Updated by CD TPM-王祥林 about 2 years ago
- Category changed from BSP to SYSTEM
- Assignee changed from CD_BSP 彭文亮 to CD SYSTEM-胡兵
旭新
请查一下第168次开机启动慢的原因。
#12 Updated by CDTS-TEST 周婷 about 2 years ago
- Assignee changed from CD SYSTEM-胡兵 to CD SYSTEM-夏旭
旭新请分析
#13 Updated by CD SYSTEM-夏旭 about 2 years ago
167 开机
kernel
01-01 08:00:05.357 0 0 I init : init first stage started!
01-01 08:00:06.687 0 0 I init : init second stage started!
01-01 08:00:08.516 0 0 I fsck.f2fs: from "4.19.157-perf+" --- 对比
没有找到对应168logandroid
行 6235: 01-01 08:00:08.376 680 680 I boot_progress_start: 5408
行 7441: 01-01 08:00:08.836 680 680 I boot_progress_preload_start: 5868
行 9697: 01-01 08:00:09.797 680 680 I boot_progress_preload_end: 6829
行 9778: 01-01 08:00:09.984 1519 1519 I boot_progress_system_run: 7016
行 10720: 01-01 08:00:10.494 1519 1519 I boot_progress_pms_start: 7526
行 11045: 01-01 08:00:10.646 1519 1519 I boot_progress_pms_system_scan_start: 7678
01-01 08:00:10.852 1519 1519 I PackageManager: Finished scanning system apps. Time: 206 ms, packageCount: 135 , timePerPackage: 1 , cached: 136 -- 对比
行 11408: 01-01 08:00:10.852 1519 1519 I boot_progress_pms_data_scan_start: 7884
行 12175: 01-01 08:00:11.688 1519 1519 I boot_progress_pms_scan_end: 8720
01-01 08:00:11.688 1519 1519 I PackageManager: Time to scan packages: 1.042 seconds --- 对比
行 12384: 01-01 08:00:11.764 1519 1519 I boot_progress_pms_ready: 8796
行 13857: 05-10 18:01:23.805 1519 1519 I boot_progress_ams_ready: 9889
行 17503: 06-21 11:32:49.311 1519 1580 I boot_progress_enable_screen: 11131
168
kernel 看起来与f2fs相关
01-01 08:00:06.570 0 0 I [ 1.330953] init: init first stage started!
01-01 08:00:06.570 0 0 I [ 2.729393] init: init second stage started!
kernel只吐出这些log
01-01 08:00:07.715 0 0 I [ 4.885283] fsck.f2fs: from "4.19.157-perf+"
01-01 08:00:09.711 0 0 E [ 6.880052] link_delay_work_func: DTC_ETH: SQI=0, link=0
01-01 08:00:13.919 0 0 I : [ 11.091805] F2FS-fs (dm-21): Adjust unusable cap for checkpoint=disable = 2849170 / 10%
01-01 08:00:14.831 0 0 E [ 12.000055] link_delay_work_func: DTC_ETH: SQI=0, link=0
01-01 08:00:19.176 0 0 W : [ 16.348293] F2FS-fs (dm-21): Start checkpoint disabled!
01-01 08:00:19.178 0 0 I : [ 16.349865] F2FS-fs (dm-21): Mounted with checkpoint version = 2088bb13
01-01 08:00:19.180 0 0 I [ 16.352437] init: Userdata mounted using /vendor/etc/fstab.qcom result : 7 ---- kernel 耗时点
android
行 12365: 01-01 08:00:19.589 701 701 I boot_progress_start: 16920
行 13836: 01-01 08:00:20.106 701 701 I boot_progress_preload_start: 17437
行 16134: 01-01 08:00:21.125 701 701 I boot_progress_preload_end: 18456
行 16239: 01-01 08:00:21.419 1580 1580 I boot_progress_system_run: 18750
行 17749: 01-01 08:00:22.431 1580 1580 I boot_progress_pms_start: 19762
行 18004: 01-01 08:00:22.532 1580 1580 I boot_progress_pms_system_scan_start: 19863
01-01 08:00:23.801 1580 1580 I PackageManager: Finished scanning system apps. Time: 1269 ms, packageCount: 136 , timePerPackage: 9 , cached: 0 -- //耗时点
行 18504: 01-01 08:00:23.801 1580 1580 I boot_progress_pms_data_scan_start: 21133
行 19319: 01-01 08:00:30.762 1580 1580 I boot_progress_pms_scan_end: 28093
01-01 08:00:30.762 1580 1580 I PackageManager: Time to scan packages: 8.231 seconds ---- // 耗时点
行 19551: 01-01 08:00:30.994 1580 1580 I boot_progress_pms_ready: 28325
行 19850: 01-01 08:00:31.333 1580 1580 I SystemServerTiming: StartAlarmManagerService
行 19857: 06-21 05:54:01.001 1580 1580 I SystemServerTiming: StartInputManagerService
// 耗时 看起来是在做dex2oat
行 20034: 06-21 05:54:01.115 1580 1580 I SystemServerTiming: UpdatePackagesIfNeeded
行 20326: 06-21 05:54:11.391 1580 1580 I SystemServerTiming: PerformFstrimIfNeeded
行 22317: 06-21 05:54:12.116 1580 1580 I boot_progress_ams_ready: 39786
行 28485: 06-21 05:54:13.627 1580 1661 I boot_progress_enable_screen: 41297测试重新验证开机时间 大概在30s 其中差异大部分为pms扫描包相关
Z:\home\he\下载\118872\正常\out\000489_merged_logcat_file.log （匹配11次）
行 8064: 01-01 08:00:18.788 700 700 I boot_progress_start: 16129
行 8289: 01-01 08:00:19.054 700 700 I boot_progress_preload_start: 16395
行 11195: 01-01 08:00:20.356 700 700 I boot_progress_preload_end: 17697
行 11400: 01-01 08:00:20.591 1529 1529 I boot_progress_system_run: 17932
行 11864: 01-01 08:00:21.041 1529 1529 I boot_progress_pms_start: 18383
行 12081: 01-01 08:00:21.141 1529 1529 I boot_progress_pms_system_scan_start: 18482
行 12706: 01-01 08:00:22.340 1529 1529 I boot_progress_pms_data_scan_start: 19681
行 13384: 01-01 08:00:23.508 1529 1529 I boot_progress_pms_scan_end: 20849
01-01 08:00:23.508 1529 1529 I PackageManager: Time to scan packages: 2.367 seconds
行 13544: 01-01 08:00:23.586 1529 1529 I boot_progress_pms_ready: 20927
行 17091: 06-21 05:54:06.643 1529 1529 I boot_progress_ams_ready: 26796
行 22612: 06-28 17:23:33.981 1529 1642 I boot_progress_enable_screen: 28085#14 Updated by 物联网测试组_CDTS 唐霞 about 2 years ago
#15 Updated by IoT scm about 2 years ago
| ID | Project | Branch | Uploader |
| 210945 | general/platform/vendor/thundercomm/apps/TCService | Pre_figure_turbox-c2130c-la1.1-qssi12-dev | wangxl0510@thundersoft.com |
| AF:MCU-UART:Notify the mcu of the completion of boot when Launcher started. TC-RID: 1201-0206901 IssueID: TS-R-BUG-118872 Change-Id: I04f44c78c2bc9348300a2a78e8bc429850811fc0 |
|||
#16 Updated by IoT scm about 2 years ago
| ID | Project | Branch | Uploader |
| 211568 | general/platform/vendor/thundercomm/apps/TCService | Pre_figure_turbox-c2130c-la1.1-qssi12-release_sorp | wangxl0510@thundersoft.com |
| AF:MCU-UART:Notify the mcu of the completion of boot when Launcher started. TC-RID: 1201-0206901 IssueID: TS-R-BUG-118872 Change-Id: I04f44c78c2bc9348300a2a78e8bc429850811fc0 (cherry picked from commit e2fa8c0fbd01ae3dd09653afb54c5c979dc247f7) |
|||
#17 Updated by CD SYSTEM-夏旭 about 2 years ago
- Status changed from New to RESOLVED
- Assignee changed from CD SYSTEM-夏旭 to 物联网测试组_CDTS 唐霞
- % Done changed from 0 to 100
- Resolution changed from -- to FIXED
- Degrated changed from -- to No
- Fixed Version set to 2023-06-30
- Root cause set to 接受开机广播慢导致mcu超时
■目前进展
相关代码已经入库
■下一步计划
等待测试复测
#18 Updated by 物联网测试组_CDTS 唐霞 almost 2 years ago
- Status changed from RESOLVED to VERIFIED
持续跟踪2周未复现，关闭问题单
#19 Updated by 物联网测试组_CDTS 唐霞 almost 2 years ago
- Status changed from VERIFIED to CLOSED