记录一次系统调用慢的 分析过程



收到问题jira描述

•   

•      [EM][] [工厂适应性问题]执行shell命令，系统反应慢

•      
分析发现调用系统system函数执行命令的时间过长，每条命令执行约250ms。对比其它平台只需要20~50ms，请安排确认一下。

•      01-01 00:01:31.816 I/sita.common(1758): cmdstring is cp -rf /userdata/FactoryData.db/mnt/usb/sda/database/userdata/

•        01-01 00:01:31.817 I/sita.common( 1758):@_@[os_cmd_system] temp_cmd_string:busybox cp -rf /userdata/FactoryData.db/mnt/usb/sda/database/userdata/

•        01-01 00:01:31.817 I/sita.common( 1758):[os_cmd_system] temp_cmd_string:busybox cp -rf /userdata/FactoryData.db/mnt/usb/sda/database/userdata/

System_call

问题确认过程

 

 

Skyworth & 566TK对比数据

•         Sky 562测试：

•         system()，测试如下：

•         [Serial-COM40619-152503-980]wysdebugcall system() begin1 0

•         [Serial-COM40619-152504-553]00:21:97:11:03:30

•         [Serial-COM40619-152504-582]wysdebugcall system() end1

 

 

•         [Serial-COM40619-152504-584]wysdebugcall system() begin1 1

•         [Serial-COM40619-152505-180]00:21:97:11:03:30

•         [Serial-COM40619-152505-181]wysdebugcall system() end1

 

•         基本每次call system耗时600ms.

 

•         566 TK 测试：  

•         [20170620_16:17:13:448] wysdebugcall system() begin 0

•         [20170620_16:17:13:557]00:21:00:87:00:01

•         [20170620_16:17:13:557] wysdebugcall system() end 0

•         [20170620_16:17:13:557] wysdebugcall system() begin 1

•         [20170620_16:17:13:651]00:21:00:87:00:01

•         [20170620_16:17:13:651] wysdebugcall system() end 1

•         Skyworth 数据和tcl一致，566tk较快，但是566 ic性能较好.

 

•      我一开始觉得这个不是主要因素.

•      Bug单的问题是pc串口工具和中间件通信超时.

•      所以做了个实验写一个main函数测了一下时间

•      gettimeofday(&t_start, NULL);

 

•      system("busybox su");

 

•      gettimeofday(&t_end, NULL);

 

•      cost_time = t_end.tv_usec -t_start.tv_usec;

 

•      printf("Cost time: %ldus", cost_time);

•      只有10ms大概

 

•      然后就回复客户请他们优化

•      把多个system call 命令组合一下

•      命令序列 ; & && ||

•      ;　　从左到右依次被执行，返回最后一个命令的执行状态

•      &　　该命令将在后台被执行，即在子bash中执行（或ctrl+z，bg， jobs，bg命令号）（变量$!、$one、$two、$three返回后台进程的pid号）

•      &&　当且仅当左边的命令退出状态为0时，才执行右边的命令（Linux中0为执行成功，非0为失败）

•      ||　 当且仅当左边的命令执行失败时才会执行右边的命令

 

 

•      客户回复如下:

•      张工：

•       

•      目前的主要问题是执行一次fpi_system_shell_cmd()的时间过长，这个项目与其它项目相差太大。

•      在这个没有办法优化的情况下再进行其它的优化，主要是因为：

•      在中间件里发命令的地方太多了

•      有些命令是必须分开，或者在不同的函数实现。

•       

•      为了这个项目又重新将多个函数整合到一起，这个方法是不可取的。

•       

•      Best regards!

•      柯杰燕(Jacky)

 

 

•      我试图再次说服客户.

•      用strace抓了一下 systemcall的细节，主要是说明这个system执行的命令还有一些不必要的，而且clone也很费资源，可能是这个导致慢.

•      system("cat /proc/mounts"); =   9次系统调用

•      {

•      rt_sigaction(SIGINT,{sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0xb62ce181},{sa_handler=SIG_IGN, sa_mask=[], sa_flags=0}, 8) = 0

•      rt_sigaction(SIGQUIT,{sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0xb62ce181},{sa_handler=SIG_IGN, sa_mask=[], sa_flags=0}, 8) = 0

•      rt_sigprocmask(SIG_BLOCK, [CHLD],[], 8) = 0 <0.000023>

•      clone(child_stack=NULL,flags=CLONE_PARENT_SETTID|SIGCHLD, parent_tidptr=0xbe2bd278) = 2884  

•      wait4(2884, [{WIFEXITED(s)&& WEXITSTATUS(s) == 0}], 0, NULL) = 2884

•      rt_sigaction(SIGINT,{sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0xb62ce181},NULL, 8) = 0

•      rt_sigaction(SIGQUIT,{sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0xb62ce181},NULL, 8) = 0

•      rt_sigprocmask(SIG_SETMASK, [],NULL, 8) = 0

•      SIGCHLD {si_signo=SIGCHLD,si_code=CLD_EXITED, si_pid=2884, si_uid=0, si_status=0, si_utime=3, si_stime=1}---

•      }

 

 

•         客户使用mstar对比log回应

•          下面是MS6586的克隆log，执行了13条指令，共花了373ms，平均每条指令的执行时间为28.6ms。USB克隆功能，会申请300K的内存来做CRC校验。从红色标注的命令来看，速度与内存的申请无关。

•                  写USB

•                  01-01 00:02:52.647 I/sita.common(  940): cmdstring is mkdir -p /mnt/usb/sda/database/userdata/

•         01-01 00:02:52.679I/sita.common(  940): cmdstring is mkdir-p /mnt/usb/sda/database/impdata/                                                       32ms

•         01-01 00:02:52.707I/sita.common(  940): cmdstring is cp -rf/userdata/FactoryData.db /mnt/usb/sda/database/userdata/         28ms

•         01-01 00:02:52.746I/sita.common(  940): cmdstring is cp -rf/impdata/white_balance.bin /mnt/usb/sda/database/impdata/       39ms

•         01-01 00:02:52.775I/sita.common(  940): cmdstring is cp -rf/impdata/panel_data.ini /mnt/usb/sda/database/impdata/              39ms

•         NT63平台同样指令的执行情况，13条指令，共花了1278ms，平均每条指令执行时间为98.3ms

•         写USB

•         01-01 00:02:02.285 I/sita.common(1580): cmdstring is mkdir -p /mnt/usb/sda/database/userdata/                         

•         01-01 00:02:02.465 I/sita.common(1580): cmdstring is mkdir -p /mnt/usb/sda/database/impdata/                                                    180ms

•         01-01 00:02:02.704 I/sita.common(1580): cmdstring is cp -rf /userdata/FactoryData.db /mnt/usb/sda/database/userdata/      239ms

•         01-01 00:02:02.870 I/sita.common(1580): cmdstring is cp -rf /impdata/white_balance.bin/mnt/usb/sda/database/impdata/      166ms

•         01-01 00:02:03.024 I/sita.common(1580): cmdstring is cp -rf /impdata/panel_data.ini/mnt/usb/sda/database/impdata/          154

 

•      应为我观察到客户打印中间有穿插其他模块的输出我就请求客户精确测量

•      2．看起来跟统计计量方法有关系 . 

•       

–  00:02:07.450 I/sita.common( 1580): temp_cmd_string = busybox mkdir -p/mnt/usb/sda/database/userdata/

•      这中间看起来是穿插了其他模块的log输出 也就是时间片被切换到其他thread了.

•      01-01 00:02:07.615 I/sita.common( 1580): ret = 0

•       

•      能否使用如下方法精确计量一下.

 

 

•       客户精测数据按照一面的方法，抓取的命令执行时间如下：确实长

•               01-0101:15:25.766 I/sita.common( 1580): system cmd = 184558

•      01-01 01:15:26.440 I/sita.common(1580): system cmd = 233624

•      01-01 01:15:26.582 I/sita.common(1580): system cmd = 141708

•      01-01 01:15:26.882 I/sita.common(1580): system cmd = 145610

•      01-01 01:15:26.986 I/sita.common(1580): system cmd = 103825

•      01-01 01:15:27.234 I/sita.common(1580): system cmd = -752604

•      01-01 01:15:27.383 I/sita.common(1580): system cmd = 148220

•      01-01 01:15:27.542 I/sita.common(1580): system cmd = 151380

•      01-01 01:15:27.688 I/sita.common(1580): system cmd = 145581

•      01-01 01:16:25.858 I/sita.common(1580): system cmd = 145867

•      01-01 01:16:26.006 I/sita.common(1580): system cmd = -852265

•      01-01 01:16:26.209 I/sita.common(1580): system cmd = 202841

•      01-01 01:16:26.440 I/sita.common(1580): system cmd = 147108

•      01-01 01:16:26.600 I/sita.common(1580): system cmd = 159468

•      01-01 01:16:26.825 I/sita.common(1580): system cmd = 224476

•      01-01 01:16:27.006 I/sita.common(1580): system cmd = -819581

•      01-01 01:16:27.702 I/sita.common(1580): system cmd = 695704

 

•      我就在nvtdebug fpp_system.cpp里增加测试代码

•      测试发现同样的一个system调用

•      从10ms变成了120ms 

•      这里才算真正问题确认了.

•      同时总部有建议从UART角度去查一下.

•      就做了实验.

•      set console tty0 xsave kercmd关闭串口log.没有效果

•      同时跟汪俊证实pc通信时会切到ttys1关闭ttys0  排除了uart的关系.

 

客户不愿修改代码,给出第一个解决方案

•      当板子收到要进入p  model 命令

•      ps 先看一下 sitatvservice的 pid

    chrt -p -r 1  pid                 

( chrt -p -r 99  pid     1~ 99是优先级需要根据实际测试情况来决定.)

当板子退出 p model时

   chrt -p -o0 pid 

提高tcl mw进程优先级之后，每条system命令大概耗时70~120ms之间，还是没有达到TCL的要求。

 

•      求救总部kris 拿走我的测试文件和方法.

•      按照Jing的環境做了個實驗

•      修改前大概145ms,修改後大概30ms

•      雖然還是比不上standalone的10ms

•      不過可能可以做個參考

 

•      二者的差別在於environment variables設定了一堆search path和preloadlibrary

•      所以我把它全清了

 

•      Note:此實驗沒有修改thread priority.

 

•      ------------------------------------------------------

•      0. Exit

•      1. fpp_system_debug_key_set

•      2.fpp_system_set_config_path_and_name

•      3. fpp_system_set_env

•      4. fpp_system_get_env

•      5. fpp_system_call_test

•      ------------------------------------------[?] help --

•      Select: 5

•      su: unknown user root

•      #Child takes around 0.03054 seconds

•      su: unknown user root

•      #Parent takes around 0.14659 seconds

 

 

•      Hi Jing,

•       

•      首先改動environment variable不確定會不會對/tvos/bin/sitatvservice其它running service有沒有影響

•       

•      我的方式可能會傾向於可能要fork一個subprocess來service那些system_api

•       

•      fork完後呼叫clearenv();把environment variables清乾淨

•       

•      不過最好的方式是review這些LD_PRELOAD, LD_LIBRARY_PATH的設定是否合理

•       

•      Regards,

•      Kris

 

 

 

•      客户不愿意改code所以fork后清环境变量的方案被否

•      Review环境变量这个影响的不只是system busybox命令

•      影响更大.

•      Hi Jing,

 如果他們使用的只有busybox command的話

•       

•      還有另一種選擇 busybox變成statically linked

•       

•      這樣大約是2x ms

•       

•      Regards,

•      Kris

 

 

•      戚工：  

 

•      经HQ大力协助分析. Runtime environment variables 非常影响busybox命令执行速度.

•      使用static busybox 可以解决这个问题.

 

 

•      操作步骤如下：

•      /bin # ls -la

•      原本busy大小     -rwxrwxr-x   1 1041    1041        697788 Jun 22 2017 busybox

 

•      新的busybox大小-rwxr-xr-x   1 0        0          1361628 Jan 1 00:02 busybox

 

 

•      使用附件的busybox替换 board里   /bin目录下原本的busybox    

•      cp后 sync

 

 

•      可以看到Cost time su: 23206 us

•        执行时间由146ms变成23ms

 

打包到boot.img产生coredump问题

•      CPU: 1 PID: 1708 Comm: mdev Tainted:G           O 3.10.0+ #1

•      task: c512df80 ti: dfe54000 task.ti:dfe54000

•      PC is at 0x0

•      LR is at 0x9aec7

•      pc : [<00000000>]    lr : [<0009aec7>]    psr: 200f0150

•      sp : be43ec50  ip : 0000000e fp : 00000000

•      r10: 00000000  r9 : 0016b02c r8 : 0016c898

•      r7 : 00000001  r6 : 0016b9a4 r5 : 00000000 r4 : 00000002

•      r3 : 0016c898  r2 : ab596f23 r1 : 00000000 r0 : 00000000

•      Flags: nzCv  IRQs on FIQs off Mode USER_32 ISA ARM Segment user

•      Control: 10c53c7d  Table: 2d21c04a  DAC: 00000015

 

 

 

•      Dear All：

 

•      透過這封Mail說明一下這個crash issue的一些前因後果，這個問題一開始是發現打開kdebugd的時候，static link的busybox在kernel開機的時候有一連串的core dump發生，因為這個問題在668的時候有發生過，當時一直以為是kdebugd porting有什麼地方跟在tk kernel與ss kernel之間的差異造成的。

 

•      這次利用這個機會花時間trace一下這個問題，中間發現，kdebugd印出來的core dump是userprogram發生segmentation fault造成的，

•      而且發生的user spaceprogram都是mdev，把環境簡化成開機進入shell之後就停止，還是會發生，而且發生的點是在註冊了hotplug的callback program，也就是mdev之後才產生。看到這個現象，初步判斷是mdev的bug，所以做了另一個測試，寫一個static link的user space program，裡面什麼事情都不做，在mainfunction裡面直接return 0返回。結果把這個user space program註冊給kernel，一樣會發生core dump。這時候debug的方向改朝向kernel的signalhandler去找，在get_signal_to_deliver裡面，把kdebugd關閉的狀況下，segmentationfault還是會發生，而且都只有在透過call_usermodehelper的方式呼叫的user space program才有這個問題。

 

 

 

 

 

•      與kris討論之後，kris從user spacedebug，發現一個很重要的線索，用來測試的static link program在crash的時候，是因為rtld_fini被呼叫了，這個function是一個callbackfunction，只有在program是dynamic link的時候才可能被呼叫，進一步比對了傳遞的參數之後，發現register a1的值並不正確，導致rtld_fini被認為有被hook進來，所以在程式結束的時候被呼叫，造成crash。

 

•      從上面的各個現象看來，問題還是出現在kernel呼叫user space program的參數傳遞上面，在load_elf_binary呼叫start_thread之前將傳遞的參數dump出來，會發現參數是錯誤的，而且這些錯誤的參數被start_thread傳給了要執行的user program。

•      比對4.1的kernel之後發現，這個問題是一個kernel bug，原本是為了執行a.out這類的執行檔做的相容性，反而會在user space program是elf格式，而且user space program是由kernel來呼叫的狀況之下出現bug，所以針對kernel進行patch，相關的patch訊息在這邊可以找到https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/arch/arm/include/asm/processor.h?id=acfdd4b1f7590d02e9bae3b73bdbbc4a31b05d38

•      以上是這個問題的一些技術細節分享，感謝kris在這個問題上提供的大力協助。

•       

•      Regards 

•      Alvin

 

Backup方案

•      即使使用动态的busybox，一个system也可以也可以缩减到 30 ms  .

 

•      根本原因是环境变量影响了 库依赖搜索时间. (LD_PRELOAD, LD_LIBRARY_PATH)

 

 

•      1.   进入pc模式时   getenv(LD_LIBRARY_PATH)     将字符串保存下来cp    unsetenv("LD_LIBRARY_PATH")                  LD_PRELOAD同样一起处理

•      2.   退出pc模式时    putenv还原环境变量  LD_PRELOAD同样一起还原

 

•      这样改动是最小的.并没有修改中间件原来的逻辑.

 

最终采用了使用静态busybox的方案

•      1.在更早的历史一直就是使用静态busybox

•      2.kdebugd加入后，暴漏了kernel的bug.才改为动态busybox .这次HQ解决了.

•      使用静态busybox优点：

•      1.开机速度加快，

•       2. busybox 里都是系统常用命令，使用静态减少库查找时间.

•      但是需要注意原本时序改变发生的一些问题:比如EGL错误的问题

•      User层速度加快之后，mali driver还未加载完成，导致错误. GSW帮忙解决