Gentoo Forums
Gentoo Forums
Gentoo Forums
Quick Search: in
Gentoo RapsberryPi eccessive lag in command execution
View unanswered posts
View posts from last 24 hours

 
Reply to topic    Gentoo Forums Forum Index Gentoo on Alternative Architectures
View previous topic :: View next topic  
Author Message
tom!79
n00b
n00b


Joined: 08 Jul 2014
Posts: 12

PostPosted: Wed Jul 09, 2014 7:46 pm    Post subject: Gentoo RapsberryPi eccessive lag in command execution Reply with quote

Hi all,
i recenly reinstalled gentoo on my raspberrypi, but i dunno why i have a sort of "lag" in terminal:

Eselect example:
Code:

myrasp ~ #: time eselect profile list
Available profile symlink targets:
  [1]   default/linux/arm/13.0
  [2]   default/linux/arm/13.0/desktop
  [3]   default/linux/arm/13.0/desktop/gnome
  [4]   default/linux/arm/13.0/desktop/gnome/systemd
  [5]   default/linux/arm/13.0/desktop/kde
  [6]   default/linux/arm/13.0/desktop/kde/systemd
  [7]   default/linux/arm/13.0/developer
  [8]   default/linux/arm/13.0/armv4
  [9]   default/linux/arm/13.0/armv4/desktop
  [10]  default/linux/arm/13.0/armv4/desktop/gnome
  [11]  default/linux/arm/13.0/armv4/desktop/kde
  [12]  default/linux/arm/13.0/armv4/developer
  [13]  default/linux/arm/13.0/armv4t
  [14]  default/linux/arm/13.0/armv4t/desktop
  [15]  default/linux/arm/13.0/armv4t/desktop/gnome
  [16]  default/linux/arm/13.0/armv4t/desktop/kde
  [17]  default/linux/arm/13.0/armv4t/developer
  [18]  default/linux/arm/13.0/armv5te
  [19]  default/linux/arm/13.0/armv5te/desktop
  [20]  default/linux/arm/13.0/armv5te/desktop/gnome
  [21]  default/linux/arm/13.0/armv5te/desktop/kde
  [22]  default/linux/arm/13.0/armv5te/developer
  [23]  default/linux/arm/13.0/armv6j *
  [24]  default/linux/arm/13.0/armv6j/desktop
  [25]  default/linux/arm/13.0/armv6j/desktop/gnome
  [26]  default/linux/arm/13.0/armv6j/desktop/kde
  [27]  default/linux/arm/13.0/armv6j/developer
  [28]  default/linux/arm/13.0/armv7a
  [29]  default/linux/arm/13.0/armv7a/desktop
  [30]  default/linux/arm/13.0/armv7a/desktop/gnome
  [31]  default/linux/arm/13.0/armv7a/desktop/kde
  [32]  default/linux/arm/13.0/armv7a/developer
  [33]  hardened/linux/arm/armv7a
  [34]  hardened/linux/arm/armv6j
  [35]  hardened/linux/uclibc/arm/armv7a
  [36]  hardened/linux/musl/arm/armv7a

real    1m15.929s
user    0m34.600s
sys     0m1.070s


After hitting enter to execute eselect, the systems seems hangs for about 40sec then do all as usual.Q

I followed the Quick Installation Guide, my SD card is a Kingstone MicroSD microSDHC/SDXC – UHS-I Class 10 32Gb

Raspberry Kernel is:
Code:
Linux version 3.12.23+ (dc4@dc4-Latitude-E6510) (gcc version 4.8.3 20140303 (prerelease) (crosstool-NG linaro-1.13.1+bzr2650 - Linaro GCC 2014.03) ) #692 PREEMPT Thu Jun 26 20:15:50 BST 2014


Partitions:
Code:
Disk /dev/mmcblk0: 29,9 GiB, 32090619904 bytes, 62676992 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0xf95114c3

Dispositivo    Avvio     Start      Fine   Blocks  Id System
/dev/mmcblk0p1            2048    206847   102400   c W95 FAT32 (LBA)
/dev/mmcblk0p2          206848   2254847  1024000  82 Linux swap / Solaris
/dev/mmcblk0p3         2254848  62676991 30211072  83 Linux


tune2fs info of root fs:

Code:
 
tune2fs -l /dev/mmcblk0p3
tune2fs 1.42.7 (21-Jan-2013)
Filesystem volume name:   <none>
Last mounted on:          /
Filesystem UUID:          b93fef38-cd29-4713-b383-2e629763559f
Filesystem magic number:  0xEF53
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr resize_inode dir_index filetype needs_recovery extent flex_bg sparse_super large_file huge_file uninit_bg dir_nlink extra_isize
Filesystem flags:         signed_directory_hash
Default mount options:    user_xattr acl
Filesystem state:         clean
Errors behavior:          Continue
Filesystem OS type:       Linux
Inode count:              1888656
Block count:              7552768
Reserved block count:     377638
Free blocks:              6898394
Free inodes:              1648894
First block:              0
Block size:               4096
Fragment size:            4096
Reserved GDT blocks:      1022
Blocks per group:         32768
Fragments per group:      32768
Inodes per group:         8176
Inode blocks per group:   511
Flex block group size:    16
Filesystem created:       Fri Jul  4 02:19:49 2014
Last mount time:          Thu Jan  1 01:00:19 1970
Last write time:          Thu Jan  1 01:00:19 1970
Mount count:              23
Maximum mount count:      -1
Last checked:             Fri Jul  4 02:19:49 2014
Check interval:           0 (<none>)
Lifetime writes:          6026 MB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:               256
Required extra isize:     28
Desired extra isize:      28
Journal inode:            8
First orphan inode:       1180229
Default directory hash:   half_md4
Directory Hash Seed:      01b743a9-dcb8-4ad0-a3ae-9593f179e27a
Journal backup:           inode blocks


I suppose that's a fs bug, maybe i have done something wrong, any idea?
Back to top
View user's profile Send private message
roarinelk
Guru
Guru


Joined: 04 Mar 2004
Posts: 520

PostPosted: Thu Jul 10, 2014 7:29 am    Post subject: Reply with quote

try to strace one of the slow commands, maybe you can find out which syscalls are
taking so long.
Back to top
View user's profile Send private message
tom!79
n00b
n00b


Joined: 08 Jul 2014
Posts: 12

PostPosted: Thu Jul 10, 2014 9:07 am    Post subject: Reply with quote

Hi roarinelk, as you suggest you can find strace at the end of this post (my skill in reading that is = 0, the only thing that i have notice is a 36sec hang near the end of strace), this morning with a less workload this is the situation, even if is smaller the delay persists:

Code:

time eselect profile list
Available profile symlink targets:
  [1]   default/linux/arm/13.0
  [2]   default/linux/arm/13.0/desktop
  [3]   default/linux/arm/13.0/desktop/gnome
  [4]   default/linux/arm/13.0/desktop/gnome/systemd
  [5]   default/linux/arm/13.0/desktop/kde
  [6]   default/linux/arm/13.0/desktop/kde/systemd
  [7]   default/linux/arm/13.0/developer
  [8]   default/linux/arm/13.0/armv4
  [9]   default/linux/arm/13.0/armv4/desktop
  [10]  default/linux/arm/13.0/armv4/desktop/gnome
  [11]  default/linux/arm/13.0/armv4/desktop/kde
  [12]  default/linux/arm/13.0/armv4/developer
  [13]  default/linux/arm/13.0/armv4t
  [14]  default/linux/arm/13.0/armv4t/desktop
  [15]  default/linux/arm/13.0/armv4t/desktop/gnome
  [16]  default/linux/arm/13.0/armv4t/desktop/kde
  [17]  default/linux/arm/13.0/armv4t/developer
  [18]  default/linux/arm/13.0/armv5te
  [19]  default/linux/arm/13.0/armv5te/desktop
  [20]  default/linux/arm/13.0/armv5te/desktop/gnome
  [21]  default/linux/arm/13.0/armv5te/desktop/kde
  [22]  default/linux/arm/13.0/armv5te/developer
  [23]  default/linux/arm/13.0/armv6j *
  [24]  default/linux/arm/13.0/armv6j/desktop
  [25]  default/linux/arm/13.0/armv6j/desktop/gnome
  [26]  default/linux/arm/13.0/armv6j/desktop/kde
  [27]  default/linux/arm/13.0/armv6j/developer
  [28]  default/linux/arm/13.0/armv7a
  [29]  default/linux/arm/13.0/armv7a/desktop
  [30]  default/linux/arm/13.0/armv7a/desktop/gnome
  [31]  default/linux/arm/13.0/armv7a/desktop/kde
  [32]  default/linux/arm/13.0/armv7a/developer
  [33]  hardened/linux/arm/armv7a
  [34]  hardened/linux/arm/armv6j
  [35]  hardened/linux/uclibc/arm/armv7a
  [36]  hardened/linux/musl/arm/armv7a

real    0m37.289s
user    0m34.650s
sys     0m0.980s


Strace -tt eselect profile list :
Code:

10:46:22.109314 read(3, "/usr/share/eselect/modules/profi"..., 128) = 43
10:46:22.115020 read(3, "", 128)        = 0
10:46:22.117626 close(3)                = 0
10:46:22.118083 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:46:22.118571 rt_sigaction(SIGINT, {0x3e448, [], 0x4000000 /* SA_??? */}, {SIG_DFL, [], 0x4000000 /* SA_??? */}, 8) = 0
10:46:22.119076 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 13613
10:46:22.119830 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:46:22.120444 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=13613, si_status=0, si_utime=0, si_stime=1} ---
10:46:22.120742 wait4(-1, 0xbea9a360, WNOHANG, NULL) = -1 ECHILD (No child processes)
10:46:22.121218 sigreturn() (mask [])   = 0
10:46:22.121697 rt_sigaction(SIGINT, {SIG_DFL, [], 0x4000000 /* SA_??? */}, {0x3e448, [], 0x4000000 /* SA_??? */}, 8) = 0
10:46:22.122511 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0
10:46:22.123027 rt_sigprocmask(SIG_BLOCK, [CHLD], [INT CHLD], 8) = 0
10:46:22.123595 rt_sigprocmask(SIG_SETMASK, [INT CHLD], NULL, 8) = 0
10:46:22.124060 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6d40068) = 13614
10:46:22.125413 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:46:22.125936 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:46:22.126575 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:46:22.127050 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:46:22.127628 rt_sigaction(SIGINT, {0x3e448, [], 0x4000000 /* SA_??? */}, {SIG_DFL, [], 0x4000000 /* SA_??? */}, 8) = 0
10:46:22.130563 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 13614
10:46:58.900656 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:46:58.901180 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=13614, si_status=0, si_utime=40, si_stime=22} ---
10:46:58.901490 wait4(-1, 0xbea9a818, WNOHANG, NULL) = -1 ECHILD (No child processes)
10:46:58.901924 sigreturn() (mask [HUP INT]) = 0
10:46:58.902474 rt_sigaction(SIGINT, {SIG_DFL, [], 0x4000000 /* SA_??? */}, {0x3e448, [], 0x4000000 /* SA_??? */}, 8) = 0
10:46:58.903350 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
10:46:58.903860 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
10:46:58.904430 read(255, "", 4450)     = 0
10:46:58.905191 exit_group(0)           = ?
10:46:58.906295 +++ exited with 0 +++


FULL REPORT ON PASTEBIN: http://pastebin.com/acmaFiLH
Back to top
View user's profile Send private message
Ant P.
Watchman
Watchman


Joined: 18 Apr 2009
Posts: 6920

PostPosted: Sat Jul 12, 2014 2:19 am    Post subject: Reply with quote

You'll need to rerun that with strace -f or strace -ff, it looks like the delay is in a child process.

Just a random guess: a delay of 30 seconds might be something network-related.
Back to top
View user's profile Send private message
tom!79
n00b
n00b


Joined: 08 Jul 2014
Posts: 12

PostPosted: Sat Jul 12, 2014 6:46 pm    Post subject: Reply with quote

Hi Ant,

i have done a strace -tt -f eselect profile list, the output is too high, so pastebin don't allow me to copy that online, i have zipped the output text here:
eselectstraceff2.zip
or
eselectstraceff2.bz2
or
eselectstraceff2.tar.gz

Ty T.
Back to top
View user's profile Send private message
freke
Veteran
Veteran


Joined: 23 Jan 2003
Posts: 1032
Location: Somewhere in Denmark

PostPosted: Wed Jul 23, 2014 7:40 pm    Post subject: Reply with quote

No clue on how to read those straces :(

Do you experience same lag executing other commands - eselect profile list takes about the same time on my Raspberry Pi, but I don't generally feel like I'm getting eccessive lag.
Back to top
View user's profile Send private message
xaviermiller
Bodhisattva
Bodhisattva


Joined: 23 Jul 2004
Posts: 8722
Location: ~Brussels - Belgique

PostPosted: Wed Jul 23, 2014 10:03 pm    Post subject: Reply with quote

With a USB hard drive and portage in a squashed filesystem:
Code:
real    0m33.564s
user    0m30.488s
sys     0m1.937s


The SD card performance are really bad. Try to put / on a USB hard drive ;)
_________________
Kind regards,
Xavier Miller
Back to top
View user's profile Send private message
tom!79
n00b
n00b


Joined: 08 Jul 2014
Posts: 12

PostPosted: Tue Dec 09, 2014 2:37 pm    Post subject: Reply with quote

I'm googling around looking for something about this problem, but i still haven't found a solution so...

To show better what i mean, a made this video.
(i'm sorry but i was hurry and i uploaded it whiout editing)

Look how much time passes between pressing the enter key and the start of the progam:

https://www.youtube.com/watch?v=NgjQSLe6fbU

Just see and tell me if is normal or not, thank you :wink:

I can do other test, if u want.

@xaviermiller
I need that raspberrypi use only a sd card no other device (maybe you are right with an external hdd or ssd over usb i maybe get better performance, if the problem is i/o access time, but for my needs i can't use that solution)
Back to top
View user's profile Send private message
Display posts from previous:   
Reply to topic    Gentoo Forums Forum Index Gentoo on Alternative Architectures All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum