/system/xbin/sh high cpu usage

Question

I'm using OS Monitor to look at CPU usage because I've noticed a drastic performance decrease lately. The app shows that system/xbin/sh is consuming anywhere from 10% to 70% of the CPU. This happens constantly, the process never stops appearing at the top of the list. I have a two questions:

1. What is system/xbin/sh?
2. What could be causing it to utilize so much of the CPU?
3. Is there a way to track which apps make calls to system/xbin/sh?

More Info:

• Android version: 4.1.2
• Phone: Motorola DROID RAZR MAXX HD
• ROM: Droid Nexesque v3.8 (AOSP-based ROM) (through safestrap)
• Rooted: yes
• not running any anti-virus or the like

adb shell top output:

PID PR CPU% S  #THR     VSS     RSS PCY UID      Name
6214  0  97% R     1 182528K  92452K     root     /system/xbin/sh
...
6211  0   0% S     1   1428K    448K     root     /system/xbin/sh
6212  0   0% S     1  53500K  52596K     root     /system/xbin/sh    
...

adb shell ps output:

USER     PID   PPID  VSIZE  RSS     WCHAN    PC         NAME
root      1     0     544    404   ffffffff 00000000 S /init
...
root      6211  1     1428   448   ffffffff 00000000 S /system/xbin/sh
root      6212  6211  53500  52596 ffffffff 00000000 S /system/xbin/sh
root      6214  6212  293976 214156 ffffffff 00000000 R /system/xbin/sh
...

cat /proc/<pid>/cmdline output:

"level 1" process: /system/xbin/sh /system/bin/debuggerd
"level 2" process: /system/xbin/sh /system/etc/init.d.loader
"level 3" process: /system/xbin/sh /system/etc/init.d.loader

/system/etc/init.d.loader contents:

#!/system/xbin/sh
############# ############# #############
# init.d.loader by puppet13th@xda
# Version 0.7 19 June 2012
# to run script in background append .bgrun to script name
# example : "myscript.bgrun"
# ############# ############# #############
logfile=/data/init.d.loader.log
loglength=65536
bgrunsign='.bgrun'
if [ -f $logfile ]
    then
    log=`cat $logfile`
    currentloglength=`length "$log"`
    if [ $currentloglength -gt $loglength ]
    then
    rm -f $logfile  fi
fi
echo " * `date` * init.d.loader start . . .">>$logfile
echo " ">>$logfile
if [ ! -d /system/etc/init.d ]
    then
    echo "  creating init.d folder . . .">>$logfile
    mount -o remount rw /system >>$logfile 2>>$logfile
    if [ -f /system/etc/init.d ]
        then
        rm -f /system/etc/init.d >>$logfile 2>>$logfile
    fi
    mkdir /system/etc/init.d >>$logfile 2>>$logfile
mount -o remount ro /system >>$logfile 2>>$logfile
fi
echo " ">>$logfile
echo " i : running init.d scripts . . .">>$logfile
for script in /system/etc/init.d/*
do
    if [ -x $script ]
    then
    bgrun=`grep $bgrunsign $script`>/dev/null
        if [ $? = 0 ]
        then
        echo "  - running $script in background . . .">>$logfile
        /system/xbin/sh $script & >>$logfile 2>>$logfile
        else
        echo "  - running $script . . .">>$logfile
        /system/xbin/sh $script>>$logfile 2>>$logfile
        fi
    fi
done
echo " ">>$logfile
echo " * `date` * init.d.loader end . . .">>$logfile
echo " ">>$logfile

/system/bin/debuggerd contents:

#!/system/xbin/sh
#init.d.loader
/system/etc/init.d.loader
/system/bin/debuggerd.bin

Checking /data/local for things other tools might have left to "plug into init": There are four empty folders and a file named RootToolsMounts. /data/local/RootToolsMounts contents:

rootfs / rootfs ro,relatime 0 0
tmpfs /dev tmpfs rw,nosuid,relatime,mode=755 0 0
devpts /dev/pts devpts rw,relatime,mode=600 0 0
proc /proc proc rw,relatime 0 0
sysfs /sys sysfs rw,relatime 0 0
none /acct cgroup rw,relatime,cpuacct 0 0
tmpfs /mnt/asec tmpfs rw,relatime,mode=755,gid=1000 0 0
tmpfs /mnt/obb tmpfs rw,relatime,mode=755,gid=1000 0 0
none /dev/cpuctl cgroup rw,relatime,cpu 0 0
tmpfs /dev tmpfs rw,nosuid,relatime,mode=755 0 0
devpts /dev/pts devpts rw,relatime,mode=600 0 0
/dev/block/platform/msm_sdcc.1/by-name/userdataorig /datamedia ext4 rw,relatime,user_xattr,barrier=1,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/userdataorig /ss ext4 rw,relatime,user_xattr,barrier=1,data=ordered 0 0
tmpfs /mnt/asec tmpfs rw,relatime,mode=755,gid=1000 0 0
tmpfs /mnt/obb tmpfs rw,relatime,mode=755,gid=1000 0 0
none /dev/cpuctl cgroup rw,relatime,cpu 0 0
/dev/block/platform/msm_sdcc.1/by-name/system /system ext4 ro,relatime,user_xattr,barrier=1,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/userdata /data ext4 rw,nosuid,nodev,noatime,nodiratime,user_xattr,barrier=0,data=ordered,noauto_da_alloc,discard 0 0
/dev/block/platform/msm_sdcc.1/by-name/cache /cache ext4 rw,nosuid,nodev,noatime,nodiratime,user_xattr,barrier=1,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/persist /persist ext4 rw,nosuid,nodev,relatime,user_xattr,barrier=1,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/modem /firmware ext4 ro,nosuid,nodev,relatime,user_xattr,barrier=1,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/pds /pds ext3 rw,nosuid,noexec,relatime,barrier=0,data=writeback 0 0
/dev/fuse /storage/sdcard0 fuse rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,allow_other 0 0
/dev/block/vold/179:97 /storage/sdcard1 vfat rw,dirsync,nosuid,nodev,noexec,relatime,uid=1000,gid=1015,fmask=0702,dmask=0702,allow_utime=0020,codepage=cp437,iocharset=iso8859-1,shortname=mixed,utf8,errors=remount-ro 0 0

Looking at /data/init.d.loader.log (~50 MB file), it is running the init.d scripts approximately every 10 seconds. I'm not too familiar with the underlying components of Android, so I'm not sure if this is a lot or not. The two scripts in /system/etc/init.d./ are init.d.loader.test and minfree.

/data/init.d.loader.log contents:

The log file is filled with these entries repeating every 10-12 seconds

...
* Sun Feb 23 18:46:09 CST 2014 * init.d.loader
start...
i: running init.d scripts...
 - running /system/etc/init.d/init.d.loader.test...
 - running /system/etc/init.d/minfree...
* Sun Feb 23 18:46:09 CST 2014 * init.d.loader
end...
* Sun Feb 23 18:46:20 CST 2014 * init.d.loader
start...
i: running init.d scripts...
 - running /system/etc/init.d/init.d.loader.test...
 - running /system/etc/init.d/minfree...
* Sun Feb 23 18:46:20 CST 2014 * init.d.loader
end...
...

init.d.loader.test contents:

#!/system/xbin/sh
# init.d.loader tester
# check /data/init.d.loader.test
echo init.d.loader test >/data/init.d.loader.test

minfree contents:

#!/system/xbin/sh
echo "2469,4938,6584,33756,36971,40186" > /sys/module/lowmemorykiller/parameters/minfree

Answer 1

My current guess is that the script took a lot of CPU time because it uses a very inefficient way of calculating the log file length, which is to read the entire log file to memory and use length. This shouldn't have been much of an issue if the log file is small, but since you said that log file's current size is more than 50MB, this shows that the log file isn't getting trimmed properly. Another concerning issue is that init scripts are supposed to only run once at startup, but this script is obviously being run periodically.

If my guess is correct, you may be able to fix this temporarily by deleting the log file, but eventually the slow down will occur again when the log file is filled again. Check if you have the latest version of your ROM, maybe it's fixed in the latest version? Otherwise if it's an unmaintained ROM, you'll need to figure out a way to fix the script.

Answer 2

I'm only GUESSING but have you tried lowering the log Buffer size? Feature is listed in Dev Options >Settings>Developer Options>Logger Buffer Size