Dotaz: pamalý výpis ls

[hajoucha]

Ahojda,

zaujala mne taková věc - server normálně funguje, ale tu a tam reaguje zpomaleně. Viz. následující výpis:

# for i in {1..10}; do time ls -l |wc -l; done
25

real    0m0.344s
user    0m0.003s
sys     0m0.019s
25

real    0m0.770s
user    0m0.002s
sys     0m0.023s
25

real    0m0.558s
user    0m0.005s
sys     0m0.017s
25

real    0m0.558s
user    0m0.007s
sys     0m0.015s
25

real    0m1.597s
user    0m0.005s
sys     0m0.021s
25

real    0m1.001s
user    0m0.005s
sys     0m0.019s
25

real    0m1.184s
user    0m0.003s
sys     0m0.020s
25

real    0m1.185s
user    0m0.004s
sys     0m0.020s
25

real    0m0.377s
user    0m0.001s
sys     0m0.026s
25

real    0m0.554s
user    0m0.002s
sys     0m0.022s

Přestože je v adresáři pouhých 25 položek, někdy trvá výpis 0.3s a někdy 1.6s. Nevím, jak zjistit, proč se to děje. Zkoušel jsem toto:

• cpu - mašina má mnoho jader, prakticky všechna jsou volná
• paměť - 64GB, 58GB free
• disk - iotop ukazuje prakticky nulovou zátěž, cca každých 5s malý výkyv v řádu 100kB/s.
• disk - zkoušel jsem vypnout uspávání, ale nepomohlo . Možná to disk ani nepodporuje.

   hdparm -S 0 /dev/sda
  
  /dev/sda:
   setting standby to 0 (off)
  

Kde je problém? Co bych ještě mohl prověřit?

---

---

Odpovědi

[z_sk]

a co da prikaz pwd?

[hajoucha]

#  pwd
/root
#

[Max]

A nemáš v tom adresáři něco připojeného/mountnutého? Případně symlink někam jinam?
Zdar Max

[hajoucha]

bohužel. Dobrá připomínka, ale nemám. Mám něco mountnutého jinde, ale tenhle adresář je na lokálním disku

# df -hT
Filesystem                  Type            Size  Used Avail Use% Mounted on

/dev/mapper/fedora-root     ext4             41G   26G   13G  67% /

[z_sk]

Mas to na LVM. Kto ti to instaloval?

[hajoucha]

ja jsem to instaloval, standardní postup pro fedoru.

[hajoucha]

# lvscan
File descriptor 3 (pipe:[4010317]) leaked on lvscan invocation. Parent PID 14718: -bash
  ACTIVE            '/dev/fedora/swap' [<6.93 GiB] inherit
  ACTIVE            '/dev/fedora/home' [<20.29 GiB] inherit
  ACTIVE            '/dev/fedora/root' [<41.55 GiB] inherit

# pvscan
File descriptor 3 (pipe:[4010317]) leaked on pvscan invocation. Parent PID 14718: -bash
  PV /dev/sda2   VG fedora          lvm2 [<68.76 GiB / 0    free]
  Total: 1 [<68.76 GiB] / in use: 1 [<68.76 GiB] / in no VG: 0 [0   ]

[hajoucha]

ovšem je tu určitá stopa - v tom lvm je /home stejně jako /root, ale v /home je mountnutý volume přes gluster:

# df -hT
Filesystem                  Type            Size  Used Avail Use% Mounted on
array1-ib:/gv0.tcp          fuse.glusterfs   21T  3.1T   17T  16% /home/users

Netuším, jestli to je vůbec možné, ale co když ls vznese dotaz, systém zkontroluje lvm, v lvm je namountovaný gluster a gluster to zpomalí, i když se vlastně dotaz gluster volume vůbec netýka?

[billgates]

Nemal by.

[PetebLazar]

Jaké jsou časy když se výstup přesměruje do souboru?

[z_sk]

resp. do /dev/shm/nieco

Ak je to terminalom, tak skus v xterm alebo on stty (CTRL+ALT+F1azFX)? Robit to aj tam?

[hajoucha]

v xtermu to mám teď. Kolega používá nějaký gnome-terminál, a tam se to chová stejně. Spíš bych myslel, že to terminálem není, ale ještě ověřím ten výstup do souboru…

[hajoucha]

to se snažím zjistit, ale moc mi to zatím nejde. Neumím přesměrovat výpis time do souboru.

[PetebLazar]

( time ls | wc -l ) >time_report.txt 2>&1

[hajoucha]

Bohužel stejný problém

# for i in {1..10}; do ( time ls | wc -l ) >>time_report.txt 2>&1; done

# cat time_report.txt 
25

real    0m0.134s
user    0m0.007s
sys     0m0.012s
25

real    0m0.143s
user    0m0.004s
sys     0m0.016s
25

real    0m1.176s
user    0m0.005s
sys     0m0.017s
25

real    0m0.349s
user    0m0.002s
sys     0m0.020s
25

real    0m0.550s
user    0m0.002s
sys     0m0.021s
25

real    0m0.551s
user    0m0.002s
sys     0m0.019s
25

real    0m1.175s
user    0m0.001s
sys     0m0.020s
25

real    0m1.173s
user    0m0.003s
sys     0m0.021s
25

real    0m0.328s
user    0m0.003s
sys     0m0.017s
25

real    0m0.772s
user    0m0.001s
sys     0m0.023s
25
real    0m0.980s
user    0m0.002s
sys     0m0.020s

[billgates]

Skus to dat ale zapisovat do nejakeho suboru, ktory nebude na danej particii, idealne do /dev/shm/time_report.txt

[hajoucha]

Je to lepší, ale i tak hodně…

# for i in {1..10}; do ( time ls | wc -l ) >>/dev/shm/time_report.txt 2>&1; done
# cat /dev/shm/time_report.txt
25

real    0m0.792s
user    0m0.001s
sys     0m0.025s
25

real    0m0.585s
user    0m0.001s
sys     0m0.025s
25

real    0m0.549s
user    0m0.003s
sys     0m0.019s
25

real    0m0.744s
user    0m0.002s
sys     0m0.020s
25

real    0m0.130s
user    0m0.002s
sys     0m0.018s
25

real    0m0.957s
user    0m0.003s
sys     0m0.017s
25

real    0m0.536s
user    0m0.004s
sys     0m0.016s
25

real    0m0.521s
user    0m0.002s
sys     0m0.020s
25

real    0m0.536s
user    0m0.007s
sys     0m0.013s
25

real    0m0.734s
user    0m0.000s
sys     0m0.019s5

[PetebLazar]

Ještě bych před spuštěním dal

unalias ls

v ubuntu to ls expanduje na barevne ls.

[billgates]

Ono to zisti, ze nejde na terminal zavolanim isatty a nebude generovat farebne somariny. Predpokladam, ze to bol dovod, preco tu niekto radil, aby to presmeroval do suboru a nie priamo posielal na terminal.

[z_sk]

Aj tak to mas divne, lebo u mna je to tak:

root@notebook:~# for i in {1..10}; do time ls -l |wc -l; done
33

real	0m0,008s
user	0m0,000s
sys	0m0,012s
33

real	0m0,007s
user	0m0,003s
sys	0m0,006s
33

real	0m0,006s
user	0m0,000s
sys	0m0,009s
33

real	0m0,005s
user	0m0,002s
sys	0m0,006s
33

real	0m0,006s
user	0m0,003s
sys	0m0,006s
33

real	0m0,006s
user	0m0,008s
sys	0m0,001s
33

real	0m0,007s
user	0m0,003s
sys	0m0,007s
33

real	0m0,006s
user	0m0,008s
sys	0m0,001s
33

real	0m0,008s
user	0m0,008s
sys	0m0,003s
33

real	0m0,007s
user	0m0,001s
sys	0m0,009s

[hajoucha]

ano, je to opravdu divné. Trvá to u mě moc dlouho. Možná něco v mapperu? Distribuce je fedora a / je tam standardně v /dev/mapper/fedora-root

[hajoucha]

dodávám ještě info o disku

# hdparm -i /dev/sda

/dev/sda:

 Model=WDC WD740GD-00FLC0, FwRev=33.08F33, SerialNo=WD-WMAKE2070837
 Config={ HardSect NotMFM HdSw>15uSec SpinMotCtl Fixed DTR>5Mbs FmtGapReq }
 RawCHS=16383/16/63, TrkSize=57600, SectSize=600, ECCbytes=74
 BuffType=DualPortCache, BuffSize=8192kB, MaxMultSect=16, MultSect=16
 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=145226112
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4 
 DMA modes:  mdma0 mdma1 mdma2 
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
 AdvancedPM=no WriteCache=enabled
 Drive conforms to: Unspecified:  ATA/ATAPI-1,2,3,4,5,6

 * signifies the current active mode

[billgates]

Este posli vypis: smartctl -a /dev/sda

Ak chyba binarka, tak doinstaluj balik smartmontools.

[PetebLazar]

A hraje v tom opakovaném výpisu vůbec fyzické IO roli, neměla by se následná čtení obsahu adresáře uspokojit přes buffery(cache)?

[hajoucha]

no, taky jsem si říkal, že by to napoprvé třeba mohl trvat dlouho, ale pak už rozhodně ne.

[hajoucha]

# smartctl -a /dev/sda
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-5.6.13-100.fc30.x86_64] (local build)
Copyright (C) 2002-19, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Western Digital Raptor
Device Model:     WDC WD740GD-00FLC0
Serial Number:    WD-WMAKE2070837
Firmware Version: 33.08F33
User Capacity:    74,355,769,344 bytes [74.3 GB]
Sector Size:      512 bytes logical/physical
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ATA/ATAPI-6 (minor revision not indicated)
Local Time is:    Thu Jul  2 21:33:39 2020 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x84) Offline data collection activity
                                        was suspended by an interrupting command from host.
                                        Auto Offline Data Collection: Enabled.
Self-test execution status:      (   0) The previous self-test routine completed
                                        without error or no self-test has ever 
                                        been run.
Total time to complete Offline 
data collection:                ( 1719) seconds.
Offline data collection
capabilities:                    (0x7b) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        Offline surface scan supported.
                                        Self-test supported.
                                        Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        No General Purpose Logging support.
Short self-test routine 
recommended polling time:        (   2) minutes.
Extended self-test routine
recommended polling time:        (  30) minutes.
Conveyance self-test routine
recommended polling time:        (   5) minutes.
SCT capabilities:              (0x001f) SCT Status supported.
                                        SCT Error Recovery Control supported.
                                        SCT Feature Control supported.

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0007   116   116   021    Pre-fail  Always       -       4725
  4 Start_Stop_Count        0x0032   100   100   040    Old_age   Always       -       50
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000b   200   200   051    Pre-fail  Always       -       0
  9 Power_On_Hours          0x0032   004   004   000    Old_age   Always       -       70314
 10 Spin_Retry_Count        0x0013   100   253   051    Pre-fail  Always       -       0
 11 Calibration_Retry_Count 0x0013   100   253   051    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       49
194 Temperature_Celsius     0x0022   131   102   000    Old_age   Always       -       19
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0012   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0012   200   200   000    Old_age   Always       -       0
199 UDMA_CRC_Error_Count    0x000a   200   253   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0009   200   179   051    Pre-fail  Offline      -       0

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
No self-tests have been logged.  [To run self-tests, use: smartctl -t]

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

[billgates]

No, az na to, ze ten disk ma len 80GB to vyzera byt v poriadku. Este daj vypis: which ls

A potom este vypis: ldd /bin/ls

[hajoucha]

# which ls
alias ls='ls --color=auto'
        /usr/bin/ls

# ldd /usr/bin/ls
        linux-vdso.so.1 (0x00007ffc5f1ec000)
        libselinux.so.1 => /usr/lib64/libselinux.so.1 (0x000014bf0f500000)
        libcap.so.2 => /usr/lib64/libcap.so.2 (0x000014bf0f4f8000)
        libc.so.6 => /usr/lib64/libc.so.6 (0x000014bf0f330000)
        libpcre2-8.so.0 => /usr/lib64/libpcre2-8.so.0 (0x000014bf0f298000)
        libdl.so.2 => /usr/lib64/libdl.so.2 (0x000014bf0f290000)
        /lib64/ld-linux-x86-64.so.2 (0x000014bf0f578000)
        libpthread.so.0 => /usr/lib64/libpthread.so.0 (0x000014bf0f268000)

[billgates]

Vyzera to byt fajn. Uz velmi neviem, skus este pozriet vypis "rpm -Va", ci tam nebudu nejake zmeny, ktore tam nemaju co robit (binarky napriklad). Vypise to zoznam suborov zmenenych oproti suborom v baliku.

[PetebLazar]

Nešlo by pomocí ltrace zjistit v jakém volaní ta úloha tráví čas? Zda tam něco výrazně svou délkou nevyčnívá.

[hajoucha]

vytvořil jsem /root/test a v něm soubor prase.

# time ltrace ls
prase
+++ exited (status 0) +++

real    0m5.657s
user    0m0.016s
sys     0m0.050s

Přijde mi divné, že ltrace nevypíše žádné volání. Na _jiném_ systému (archlinux, ssd disk):

 time ltrace ls
__cxa_atexit(0x55eb66c43f50, 0, 0x55eb66c59008, 0x736c6974756572)       = 0
prase
+++ exited (status 0) +++

real    0m0.024s
user    0m0.008s
sys     0m0.017s

[hajoucha]

Omlouvám se, mělo jít o strace. Ten je podstatně ukecanější.

( strace -tt -T time ls | wc -l) >/dev/shm/time_report.txt 2>&1 

[PetebLazar]

08:24:35.190458 execve("/usr/bin/time", ["time", "ls"], 0x7ffd5bd7f6a8 /* 87 vars */) = 0 <0.000206>
08:24:35.190839 brk(NULL)               = 0x56489041f000 <0.000007>
08:24:35.190880 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000010>
08:24:35.190918 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000008>
08:24:35.190953 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000011>
08:24:35.190986 fstat(3, {st_mode=S_IFREG|0644, st_size=278887, ...}) = 0 <0.000007>
08:24:35.191021 mmap(NULL, 278887, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f89302e4000 <0.000009>
08:24:35.191051 close(3)                = 0 <0.000007>
08:24:35.191088 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000009>
08:24:35.191129 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000011>
08:24:35.191162 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832 <0.000008>
08:24:35.191192 fstat(3, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0 <0.000007>
08:24:35.191221 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f89302e2000 <0.000009>
08:24:35.191253 mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f892fd11000 <0.000010>
08:24:35.191283 mprotect(0x7f892fef8000, 2097152, PROT_NONE) = 0 <0.000015>
08:24:35.191318 mmap(0x7f89300f8000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f89300f8000 <0.000012>
08:24:35.191354 mmap(0x7f89300fe000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f89300fe000 <0.000009>
08:24:35.191388 close(3)                = 0 <0.000007>
08:24:35.191426 arch_prctl(ARCH_SET_FS, 0x7f89302e3500) = 0 <0.000007>
08:24:35.191499 mprotect(0x7f89300f8000, 16384, PROT_READ) = 0 <0.000009>
08:24:35.191538 mprotect(0x56488f010000, 4096, PROT_READ) = 0 <0.000008>
08:24:35.191569 mprotect(0x7f8930329000, 4096, PROT_READ) = 0 <0.000010>
08:24:35.191598 munmap(0x7f89302e4000, 278887) = 0 <0.000015>
08:24:35.191651 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f89302e37d0) = 41278 <0.000040>
08:24:35.191715 rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f892fd4ff20}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 <0.000008>
08:24:35.191751 rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f892fd4ff20}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 <0.000007>
08:24:35.191783 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, {ru_utime={tv_sec=0, tv_usec=0}, ru_stime={tv_sec=0, tv_usec=863}, ...}) = 41278 <0.000782>
08:24:35.192591 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=41278, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
08:24:35.192610 rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f892fd4ff20}, {sa_handler=SIG_IGN, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f892fd4ff20}, 8) = 0 <0.000008>
08:24:35.192642 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f892fd4ff20}, {sa_handler=SIG_IGN, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f892fd4ff20}, 8) = 0 <0.000007>
08:24:35.192693 write(2, "0.00", 40.00)     = 4 <0.000010>
08:24:35.192724 write(2, "u", 1u)        = 1 <0.000007>
08:24:35.192752 write(2, "s", 1s)        = 1 <0.000008>
08:24:35.192781 write(2, "e", 1e)        = 1 <0.000008>
08:24:35.192809 write(2, "r", 1r)        = 1 <0.000008>
08:24:35.192837 write(2, " ", 1 )        = 1 <0.000007>
08:24:35.192866 write(2, "0.00", 40.00)     = 4 <0.000007>
08:24:35.192894 write(2, "s", 1s)        = 1 <0.000007>
08:24:35.192922 write(2, "y", 1y)        = 1 <0.000007>
08:24:35.192950 write(2, "s", 1s)        = 1 <0.000007>
08:24:35.192978 write(2, "t", 1t)        = 1 <0.000008>
08:24:35.193007 write(2, "e", 1e)        = 1 <0.000008>
08:24:35.193039 write(2, "m", 1m)        = 1 <0.000007>
08:24:35.193068 write(2, " ", 1 )        = 1 <0.000009>
08:24:35.193102 write(2, "0:00.00", 70:00.00)  = 7 <0.000007>
08:24:35.193130 write(2, "e", 1e)        = 1 <0.000009>
08:24:35.193160 write(2, "l", 1l)        = 1 <0.000007>
08:24:35.193187 write(2, "a", 1a)        = 1 <0.000008>
08:24:35.193215 write(2, "p", 1p)        = 1 <0.000006>
08:24:35.193241 write(2, "s", 1s)        = 1 <0.000008>
08:24:35.193269 write(2, "e", 1e)        = 1 <0.000008>
08:24:35.193297 write(2, "d", 1d)        = 1 <0.000008>
08:24:35.193325 write(2, " ", 1 )        = 1 <0.000007>
08:24:35.193353 write(2, "?%", 2?%)       = 2 <0.000008>
08:24:35.193381 write(2, "C", 1C)        = 1 <0.000008>
08:24:35.193409 write(2, "P", 1P)        = 1 <0.000008>
08:24:35.193437 write(2, "U", 1U)        = 1 <0.000007>
08:24:35.193465 write(2, " ", 1 )        = 1 <0.000007>
08:24:35.193493 write(2, "(", 1()        = 1 <0.000007>
08:24:35.193521 write(2, "0", 10)        = 1 <0.000007>
08:24:35.193549 write(2, "a", 1a)        = 1 <0.000007>
08:24:35.193577 write(2, "v", 1v)        = 1 <0.000007>
08:24:35.193605 write(2, "g", 1g)        = 1 <0.000008>
08:24:35.193634 write(2, "t", 1t)        = 1 <0.000008>
08:24:35.193662 write(2, "e", 1e)        = 1 <0.000008>
08:24:35.193692 write(2, "x", 1x)        = 1 <0.000008>
08:24:35.193724 write(2, "t", 1t)        = 1 <0.000012>
08:24:35.193759 write(2, "+", 1+)        = 1 <0.000006>
08:24:35.193785 write(2, "0", 10)        = 1 <0.000006>
08:24:35.193811 write(2, "a", 1a)        = 1 <0.000006>
08:24:35.193837 write(2, "v", 1v)        = 1 <0.000006>
08:24:35.193862 write(2, "g", 1g)        = 1 <0.000006>
08:24:35.193888 write(2, "d", 1d)        = 1 <0.000006>
08:24:35.193914 write(2, "a", 1a)        = 1 <0.000005>
08:24:35.193939 write(2, "t", 1t)        = 1 <0.000006>
08:24:35.193965 write(2, "a", 1a)        = 1 <0.000005>
08:24:35.193990 write(2, " ", 1 )        = 1 <0.000006>
08:24:35.194016 write(2, "2752", 42752)     = 4 <0.000006>
08:24:35.194042 write(2, "m", 1m)        = 1 <0.000005>
08:24:35.194067 write(2, "a", 1a)        = 1 <0.000006>
08:24:35.194099 write(2, "x", 1x)        = 1 <0.000006>
08:24:35.194125 write(2, "r", 1r)        = 1 <0.000006>
08:24:35.194151 write(2, "e", 1e)        = 1 <0.000005>
08:24:35.194176 write(2, "s", 1s)        = 1 <0.000005>
08:24:35.194201 write(2, "i", 1i)        = 1 <0.000006>
08:24:35.194227 write(2, "d", 1d)        = 1 <0.000005>
08:24:35.194252 write(2, "e", 1e)        = 1 <0.000006>
08:24:35.194278 write(2, "n", 1n)        = 1 <0.000006>
08:24:35.194303 write(2, "t", 1t)        = 1 <0.000006>
08:24:35.194329 write(2, ")", 1))        = 1 <0.000006>
08:24:35.194354 write(2, "k", 1k)        = 1 <0.000006>
08:24:35.194380 write(2, "\n", 1
)       = 1 <0.000006>
08:24:35.194406 write(2, "0", 10)        = 1 <0.000005>
08:24:35.194431 write(2, "i", 1i)        = 1 <0.000006>
08:24:35.194457 write(2, "n", 1n)        = 1 <0.000005>
08:24:35.194482 write(2, "p", 1p)        = 1 <0.000006>
08:24:35.194508 write(2, "u", 1u)        = 1 <0.000005>
08:24:35.194533 write(2, "t", 1t)        = 1 <0.000006>
08:24:35.194559 write(2, "s", 1s)        = 1 <0.000005>
08:24:35.194584 write(2, "+", 1+)        = 1 <0.000006>
08:24:35.194610 write(2, "0", 10)        = 1 <0.000006>
08:24:35.194636 write(2, "o", 1o)        = 1 <0.000006>
08:24:35.194661 write(2, "u", 1u)        = 1 <0.000005>
08:24:35.194683 write(2, "t", 1t)        = 1 <0.000005>
08:24:35.194704 write(2, "p", 1p)        = 1 <0.000005>
08:24:35.194724 write(2, "u", 1u)        = 1 <0.000004>
08:24:35.194743 write(2, "t", 1t)        = 1 <0.000005>
08:24:35.194764 write(2, "s", 1s)        = 1 <0.000004>
08:24:35.194784 write(2, " ", 1 )        = 1 <0.000005>
08:24:35.194804 write(2, "(", 1()        = 1 <0.000005>
08:24:35.194825 write(2, "0", 10)        = 1 <0.000005>
08:24:35.194845 write(2, "m", 1m)        = 1 <0.000004>
08:24:35.194865 write(2, "a", 1a)        = 1 <0.000006>
08:24:35.194887 write(2, "j", 1j)        = 1 <0.000006>
08:24:35.194909 write(2, "o", 1o)        = 1 <0.000006>
08:24:35.194934 write(2, "r", 1r)        = 1 <0.000006>
08:24:35.194956 write(2, "+", 1+)        = 1 <0.000006>
08:24:35.194979 write(2, "115", 3115)      = 3 <0.000006>
08:24:35.195001 write(2, "m", 1m)        = 1 <0.000006>
08:24:35.195023 write(2, "i", 1i)        = 1 <0.000006>
08:24:35.195046 write(2, "n", 1n)        = 1 <0.000006>
08:24:35.195068 write(2, "o", 1o)        = 1 <0.000006>
08:24:35.195094 write(2, "r", 1r)        = 1 <0.000006>
08:24:35.195117 write(2, ")", 1))        = 1 <0.000006>
08:24:35.195139 write(2, "p", 1p)        = 1 <0.000006>
08:24:35.195161 write(2, "a", 1a)        = 1 <0.000006>
08:24:35.195183 write(2, "g", 1g)        = 1 <0.000006>
08:24:35.195204 write(2, "e", 1e)        = 1 <0.000005>
08:24:35.195224 write(2, "f", 1f)        = 1 <0.000005>
08:24:35.195244 write(2, "a", 1a)        = 1 <0.000005>
08:24:35.195264 write(2, "u", 1u)        = 1 <0.000005>
08:24:35.195284 write(2, "l", 1l)        = 1 <0.000006>
08:24:35.195307 write(2, "t", 1t)        = 1 <0.000006>
08:24:35.195329 write(2, "s", 1s)        = 1 <0.000006>
08:24:35.195351 write(2, " ", 1 )        = 1 <0.000006>
08:24:35.195373 write(2, "0", 10)        = 1 <0.000006>
08:24:35.195396 write(2, "s", 1s)        = 1 <0.000005>
08:24:35.195418 write(2, "w", 1w)        = 1 <0.000006>
08:24:35.195440 write(2, "a", 1a)        = 1 <0.000006>
08:24:35.195462 write(2, "p", 1p)        = 1 <0.000006>
08:24:35.195485 write(2, "s", 1s)        = 1 <0.000005>
08:24:35.195507 write(2, "\n", 1
)       = 1 <0.000006>
08:24:35.195537 exit_group(0)           = ?
08:24:35.195604 +++ exited with 0 +++
1

[hajoucha]

# ( strace -tt -T time ls | wc -l) >/dev/shm/time_report.txt 2>&1
# cat /dev/shm/time_report.txt
strace: Can't stat 'time': No such file or directory
0

Přítom:

# time

real    0m0.000s
user    0m0.000s
sys     0m0.000s

Tak tedy nevím.

[hajoucha]

# strace ls 2> strace_ls.txt
prase  strace_ls.txt

# cat strace_ls.txt 
execve("/usr/bin/ls", ["ls"], 0x7ffd394cff80 /* 48 vars */) = 0
brk(NULL)                               = 0x55f742164000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd3b095090) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/tls/x86_64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/tls/x86_64/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/tls/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/tls/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/tls/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/tls", 0x7ffd3b0942e0)    = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/x86_64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/x86_64/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/lib/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/lib", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/tls/x86_64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/tls/x86_64/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/tls/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/tls/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/tls/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/tls", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/x86_64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/x86_64/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64/x86_64", 0x7ffd3b0942e0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/ibm/ibmcmp/lib64", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
openat(AT_FDCWD, "tls/x86_64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=111267, ...}) = 0
mmap(NULL, 111267, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f13cb470000
close(3)                                = 0
openat(AT_FDCWD, "/usr/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\210\0\0\0\0\0\0"..., 832) = 832
lseek(3, 163112, SEEK_SET)              = 163112
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
fstat(3, {st_mode=S_IFREG|0755, st_size=281840, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13cb48e000
lseek(3, 163112, SEEK_SET)              = 163112
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 181744, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13cb440000
mprotect(0x7f13cb447000, 139264, PROT_NONE) = 0
mmap(0x7f13cb447000, 106496, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f13cb447000
mmap(0x7f13cb461000, 28672, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x21000) = 0x7f13cb461000
mmap(0x7f13cb469000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7f13cb469000
mmap(0x7f13cb46b000, 5616, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f13cb46b000
close(3)                                = 0
openat(AT_FDCWD, "/opt/lib/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib64/libcap.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360#\0\0\0\0\0\0"..., 832) = 832
lseek(3, 19120, SEEK_SET)               = 19120
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
fstat(3, {st_mode=S_IFREG|0755, st_size=34472, ...}) = 0
lseek(3, 19120, SEEK_SET)               = 19120
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 24888, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13cb438000
mmap(0x7f13cb43a000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f13cb43a000
mmap(0x7f13cb43c000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0x7f13cb43c000
mmap(0x7f13cb43d000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0x7f13cb43d000
close(3)                                = 0
openat(AT_FDCWD, "/opt/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P@\2\0\0\0\0\0"..., 832) = 832
lseek(3, 792, SEEK_SET)                 = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0Q7r6\255\1\200\216&@L\230\372\244\35r"..., 68) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=5589976, ...}) = 0
lseek(3, 792, SEEK_SET)                 = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0Q7r6\255\1\200\216&@L\230\372\244\35r"..., 68) = 68
lseek(3, 864, SEEK_SET)                 = 864
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 1857280, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13cb270000
mprotect(0x7f13cb292000, 1679360, PROT_NONE) = 0
mmap(0x7f13cb292000, 1363968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f13cb292000
mmap(0x7f13cb3df000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16f000) = 0x7f13cb3df000
mmap(0x7f13cb42c000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bb000) = 0x7f13cb42c000
mmap(0x7f13cb432000, 14080, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f13cb432000
close(3)                                = 0
openat(AT_FDCWD, "/opt/lib/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/x86_64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/x86_64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260$\0\0\0\0\0\0"..., 832) = 832
lseek(3, 580968, SEEK_SET)              = 580968
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
fstat(3, {st_mode=S_IFREG|0755, st_size=642616, ...}) = 0
lseek(3, 580968, SEEK_SET)              = 580968
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 590408, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13cb1d8000
mprotect(0x7f13cb1da000, 577536, PROT_NONE) = 0
mmap(0x7f13cb1da000, 409600, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f13cb1da000
mmap(0x7f13cb23e000, 163840, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x66000) = 0x7f13cb23e000
mmap(0x7f13cb267000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x8e000) = 0x7f13cb267000
close(3)                                = 0
openat(AT_FDCWD, "/opt/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/x86_64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/x86_64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\22\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=52800, ...}) = 0
mmap(NULL, 20784, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13cb1d0000
mmap(0x7f13cb1d1000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7f13cb1d1000
mmap(0x7f13cb1d3000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f13cb1d3000
mmap(0x7f13cb1d4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f13cb1d4000
close(3)                                = 0
openat(AT_FDCWD, "/opt/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/opt/ibm/ibmcmp/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0r\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=698312, ...}) = 0
lseek(3, 808, SEEK_SET)                 = 808
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 132288, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13cb1a8000
mmap(0x7f13cb1ae000, 61440, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f13cb1ae000
mmap(0x7f13cb1bd000, 24576, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x7f13cb1bd000
mmap(0x7f13cb1c3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a000) = 0x7f13cb1c3000
mmap(0x7f13cb1c5000, 13504, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f13cb1c5000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13cb48c000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13cb46e000
arch_prctl(ARCH_SET_FS, 0x7f13cb48d680) = 0
mprotect(0x7f13cb42c000, 16384, PROT_READ) = 0
mprotect(0x7f13cb1c3000, 4096, PROT_READ) = 0
mprotect(0x7f13cb1d4000, 4096, PROT_READ) = 0
mprotect(0x7f13cb267000, 4096, PROT_READ) = 0
mprotect(0x7f13cb43d000, 4096, PROT_READ) = 0
mprotect(0x7f13cb469000, 4096, PROT_READ) = 0
mprotect(0x55f740f79000, 8192, PROT_READ) = 0
mprotect(0x7f13cb4ba000, 4096, PROT_READ) = 0
munmap(0x7f13cb470000, 111267)          = 0
set_tid_address(0x7f13cb48d950)         = 25327
set_robust_list(0x7f13cb48d960, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f13cb1aec50, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f13cb1bac70}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f13cb1aecf0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f13cb1bac70}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
statfs("/sys/fs/selinux", {f_type=SELINUX_MAGIC, f_bsize=4096, f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0
statfs("/sys/fs/selinux", {f_type=SELINUX_MAGIC, f_bsize=4096, f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0
brk(NULL)                               = 0x55f742164000
brk(0x55f742185000)                     = 0x55f742185000
access("/etc/selinux/config", F_OK)     = 0
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=217750512, ...}) = 0
mmap(NULL, 217750512, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f13be1f8000
close(3)                                = 0
ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(1, TIOCGWINSZ, {ws_row=58, ws_col=191, ws_xpixel=1910, ws_ypixel=1160}) = 0
openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents64(3, /* 4 entries */, 32768)   = 120
getdents64(3, /* 0 entries */, 32768)   = 0
close(3)                                = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x8), ...}) = 0
write(1, "prase  strace_ls.txt\n", 21)  = 21
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

[hajoucha]

Zjevně mu něco chybí v /opt, ale nechápu, proč ls v /root/test potřebuje vědět něco o /opt/ibm …?

[PetebLazar]

Ha! Už jsem na to přišel. Někdo (asi kolega) nastavil pro roota proměnnou

export LD_LIBRARY_PATH="/opt/lib:/opt/ibm/ibmcmp/lib64:$LD_LIBRARY_PATH"

Ovšem /opt je mountováno přes gluster:

# mount |grep opt
array1-ib:/gv02.tcp on /opt type fuse.glusterfs (rw,relatime,user_id=0,group_id=0,default_permissions,allow_other,max_read=131072)

Takže vždy trvalo, než se gluster připojil. Je to trochu divné, proč glusteru tak dlouho trvá se připojit, ale člověk alespoň tak nějak přijme, že po síti to trvá déle než lokálně.

[PetebLazar]

Gratuluji.

Když se v terminálu zbaví LD_LIBRARY_PATH té cluster-fs cesty pak to již probíhá rychle?

I když dílčí časy strace neukázal přesto navedl.

Jak je vidět tak představivosti není nikdy dost. Analýzy výše (i má) zpochybňovaly vliv fyzického IO a zapoměly že určitá fyzická IO se nemusí cachovat.

[hajoucha]

jo, teď už to běží OK. time ls je v řádu ms.

[billgates]

Nie je ta particia nahodou na nejakom HW RAID5/RAID6 alebo niecom podobnom, kedze sa jedna o server? Kazdopadne, ako dalsi pokus by som skusil primountovat s noatime a pozrel, ci sa to nezmeni. Sice netusim, preco by mal vypis ls accessovat dane subory, ale tak, treba skusit vsetko. Stretol som sa uz s auditovacim kernel modulom, ktory kontroloval obsah suboru uz pri pokuse o stat.

Taktiez moze byt server napadnuty a syscally su odklanane, co moze kludne sposobovat toto spomalenie. Tu by zasa pomohlo nabootovat z usb/cd/siete a pozriet, ci neboli zmenene niektore subory oproti verziam z balikov.

[hajoucha]

Skus strace aj s casom

strace -tt ls

[hajoucha]

jojo, viz. výše.

[hajoucha]

Tak pomocí strace myslím příčina odhalena. Moc děkuji za pomoc.

[jiwopene]

Někdy je výpis pomalý také kvůli řazení výstupu. Pokud je v adresáři ≥ pár set tisíc souborů, je to znát. Řazení se vypne pomocí -f: ls -f.