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



收到问题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+zbg jobsbg命令号)(变量$!$one$two$three返回后台进程的pid

      && 当且仅当左边的命令退出状态为0时,才执行右边的命令(Linux0为执行成功,非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.6msUSB克隆功能,会申请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

      雖然還是比不上standalone10ms

      不過可能可以做個參考

 

      二者的差別在於environment variables設定了一堆search pathpreloadlibrary

      所以我把它全清了

 

      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一個subprocessservice那些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 linkbusyboxkernel開機的時候有一連串的core dump發生,因為這個問題在668的時候有發生過,當時一直以為是kdebugd porting有什麼地方跟在tk kernelss kernel之間的差異造成的。

 

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

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

 

 

 

 

 

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

 

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

      比對4.1kernel之後發現,這個問題是一個kernel bug,原本是為了執行a.out這類的執行檔做的相容性,反而會在user space programelf格式,而且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加入后,暴漏了kernelbug.才改为动态busybox .这次HQ解决了.

      使用静态busybox优点:

      1.开机速度加快,

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

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

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

 

展开阅读全文

没有更多推荐了,返回首页