Käskyn suorittamiseen kuluvaa aikaa mittaava skripti

[petteriIII]

Taas kertaalleen petyin käyttöjärjestelmän time-käskyyn kun sen tarkkuus on huono ja sen arvot vaihtelevat - ja kyllä tajuan sen välttävän esittämästä tarkkoja kestoaikoja kun tulokset jokatapauksessa vaihtelevat kerrasta toiseen. Tämä skripti esittää tarkkoja lukemia ja jolla on vielä  suurempi resoluutio. Tein sen siksi että saisin luotettavasti mitattua kuinka BASH:in kiihdytys toimii. Käytännön esimerkki: tiedätkö mitä käskyjä kannattaa käyttää jotta skriptistä tulisi nopea? Vaikka nopeus ei sinänsä merkitsekään mitään niin turha tuhlaus särkee sielua. Enää ei tarvitse  pähkäillä kunpi on nopeampi: echo * vai: ls /home/$USER kun sen voi tällä skriptillä mitata tarkkemmin kuin haluaakaan:
- echo *   kestää minun koneessani .36ms
- ls /home/$user kestää minun koneessani 1.15ms

- monirivinen skriptikin on käsky. Kyllä se tuonne mahtuu.

Tottakai täytyy ottaa huomioon että tämä skriptin tulokset ovat vain tilastollisesti oikeita. Muuten: Linuxilla keskipoikkeamat sun muut saisi helposti laskettua ja kenties ne tarjoisivat merkityksellistä tietoa.
 
Skriptiä ole vielä hiottu ollenkaan - siinä on vielä ilmanmuuta vielä paranneltavaa.  Jos viitsii.

- repoissa on varmaankin parempiakin ratkaisuja kuin tämä. Mutta miksi käyttää niitä - viihdykettähän tämmöisten tekeminen on eikä käskyn suoritusajan mittaamisessa ole mieltä  -  eiköhän ne mittaajat ole muualla.

Koodia: [Valitse]

#!/bin/bash
# skripti on tarkoitettu nopeiden ilmiöiden luotettavaan mittaamiseen: siis alta sekunnin kestävien. Mutta kyllä tämä toimii vaikka tunnin kestävillekin.
# tämän skriptin toiminta-aika on tajuttoman pitkä: 10 sekunnista ylöspäin ja jo yhden sekunnin kestävän käskyn suoritusajan mittaaminen kestää noin 16 minuutia. Mutta tällä
# skriptillä saa mitattua asioita joita ei muuten saa mitattua: esimerkiksi mikä on tarkka nopeusero käskyillä: echo * ja: ls /home/$USER .
# Mittaustarkkuus on luokkaa .003 millisekuntia. Ota kuitenkin huomioon että tämä on tilastollinen mittaus.
# Pitää heti kertoa että sleep 1 on tosiaankin arvoltaan luokkaa 1002.8 ms
Alkuhetki=$(date +%s.%N)
for (( n=1; n<=1000; n++ )); do 
  sleep .01 # tämä käsky vakavoittaa mittaustuloksia. Tämä arvo otetaan laskuissa huomioon. Mittausaika kylläkin kasvaa. Riviä ei saa poistaa.
  # ajoitettavat käskyt kirjoitetaan seuraaville riveille; jos esimerkiksi vertaillaan joitain käskyjä niin toinen kommentoidaan kun toisen kommentti poistetaan. Riviä ei saa poistaa
  # echo *
  ls /home/$USER
  # ajoitettavien käskyjen täytyy olla kirjoitetut ennen tätä riviä. Riviä ei saa poistaa
done
Loppuhetki=$(date +%s.%N)
Kokonaisaika=$(echo $Loppuhetki-$Alkuhetki-10.596 | bc)
echo 'kulunut aika millisekunneissa 1000 mittauksen keskiarvona= '$Kokonaisaika


[_Pete_]

Miksi tämä on tarkempi kuin time? Vaihtelu vaan tapahtuu eri paikassa. Parempi olisi ymmärtää mistä vaihtelu johtuu ja ottaa se huomioon tai yrittää minimoida sitä.

[nm]

Miksi tämä on tarkempi kuin time? Vaihtelu vaan tapahtuu eri paikassa. Parempi olisi ymmärtää mistä vaihtelu johtuu ja ottaa se huomioon tai yrittää minimoida sitä.

Pointtina on ajaa suoritettavaa komentoa/ohjelmaa silmukassa tarpeeksi monta kertaa, jotta keskimääräinen suoritusaika saadaan mitattua tarkasti. Yksittäisten ajojen suoritusaikoihin tulee huomattavaa vaihtelua jo pelkästään käyttöjärjestelmän kontekstivaihdoista ja keskeytyksistä. Ajan mittaaminen voidaan toki tehdä myös time-komennolla, jos ajaa mitattavaa ohjelmaa samaan tapaan loopissa sen sisällä.

Joskus on tietysti tarpeen mitata myös hajontaa ja minimi- ja maksimiaikoja, jolloin pitäisi lisäksi mitata yksittäisten ajojen suoritusajat. Jos mitattavan ohjelman suoritusaika on kovin lyhyt, sekunnin osia, ajan mittaus pitäisi tehdä ohjelman sisällä samassa prosessissa. Profilointityökaluista voisi myös olla apua.

[petteriIII]

Miksi tämä on tarkempi kuin time? Vaihtelu vaan tapahtuu eri paikassa. Parempi olisi ymmärtää mistä vaihtelu johtuu ja ottaa se huomioon tai yrittää minimoida sitä.

Ei skriptini ole välttämättä tarkempi kuin time-käsky - ei sitä kai millään voi todeta? Mutta skriptin perättäiset tulokset ovat huomattavasti toistettavampia kuin time-käskyllä saatavat ja "ulostulo seuraa sisäänmenoa".

Skripti ei käytäkään time-käskyä vaan date-käskyä joka on tuoreempi kuin time-käsky ja siitä saa enemmän numeroita. Ainakin olettaisin että ne date-käskyn numerot eivät ole oikeita - muissa yhteyksissä on kyllä selvinnyt että ehkä yksi numero enemmän on oikea. Mutta niistä voi muodostaa keskiarvoa joka on toistettava.
- muisti pätkii näin flunssassa: ei keskiarvon ottaminen alkuunsa tuonutkaan oleellista parannusta. Mutta se mittausten välinen 10ms odotusaika teki ihmeitä; ehkä se pudotti pois sotkemasta jonkun kontekstinvaihdon tai muun.

Ja osuit ihan oikeaan:  tämä on yritys minimoida vaihteluita.  Time-käskyllä se vaan ei onnistu.

[nm]

Ja osuit ihan oikeaan:  tämä on yritys minimoida vaihteluita.  Time-käskyllä se vaan ei onnistu.

Silmukan suoritusajan voi kuitenkin mitata myös bashin sisäänrakennetulla time-kutsulla, joskin mittaustuloksen kaappaaminen on hieman kömpelöä, jos samalla halutaan, että ajettavan komennon stdout-tuloste ohjautuu päätteeseen. Tässä yksi mahdollinen toteutusesimerkki:

Koodia: [Valitse]

#!/bin/bash

TIMEFORMAT=%3R

{ time for (( n=1; n<=1000; n++ )); do sleep .01; done } 2> time.sleep.tmp
{ time for (( n=1; n<=1000; n++ )); do sleep .01; ls /home/$USER; done } 2> time.total.tmp

sleeptime=$(cat time.sleep.tmp)
totaltime=$(cat time.total.tmp)
runtime=$(echo "$totaltime-$sleeptime" | bc -l)
avgtime=$(echo "$runtime/1000.0" | bc -l)

#echo "Sleep: $sleeptime"
echo "Average: $avgtime"


[petteriIII]

Koneessa käskyjen suoritusajat ovat epämääräisiä; joskus käsky kestää 2ms ja joskus se kestää 5ms. Ja alta puoli-millisekuntia kestävät suoritusajat pyöristetään nollaksi. Eikä aika ole tuonut tähän helpotusta eikä varmaan tuokaan - syyn tähän voisi esittää useammallakin tavalla:
- minkä intel tuo sen softa vie
- Torvalds esitti homman näin: "Linux ydin on turvonnut". Siis syyllinen on käyttöjärjestelmä. Saattaa käydä jopa niin että epämääräisyys alkaa kasvamaan sillä samalla kun ydin turpoaa niin sen ylläpitäjät vähenee eivätkä kerkiä tekemään aikaisemmin tehtyyn uusien lisäyksien vaatimia muutoksia.

Käskyn suoritusaikaa ei voi mitata mittaamalla kuinka kauan perättäisten samojen käskyjen suoritus keskimäärin kestää, sillä käskyä suoritettaessa sen koodi kännetään cacheen josta se toteutetaan.
- siis tällätavoin ei saa käskeä: for (( n=1; n<=1000; n++ )); do käsky; done
sillä kun seuraava käsky on sama kuin edellinenkin niin sen käännetty koodi on jo cachessa ja suoritus on tosinopea. Käskyn suoritusaika tuleekin mitata käskemällä esimerkiksi:
for (( n=1; n<=1000; n++ )); do { käsky; sleep .001}; done jolloin käsky-koodi joudutaa jokakerralla kääntämään uudestaan - loppuajassa täytyy sitten huomioda tuo että se "sleep .001":n aika täytyy vähentää.

Tuo mitattava on lauseessa: { echo a ; sleep .001 ;}
mitattava siinä on: echo a
ja kaikki muu on aina sama. Siis kun mitataan kauanko käsky:du kestää tulisi mitattavaksi: { du ; sleep .001 ;}

Koodia: [Valitse]

#!/bin/bash
# petteriIII 16.10.2015. muistutus:  echo a kestää noin .17ms
# skripti on tarkoitettu käskyjen&"yksi tai monirivisten skriptien" suoritusajan luotettavaan mittaamiseen kun niiden suoritusajat vaihtelevat nolla-ajasta äärettömään aikaan. Mittausten
# toistettavuus pitkäkestoisissa mittauksissa on 0.1 ms, 10ms kestävissä mittauksissa 0.04ms ja alle puoli-millisekuntia kestävissä mittauksissa 0.01ms.
#
# skripti päättelee itse kuinka monesta mittauksesta sen tulee muodostaa keskiarvo. Mitattaessa alle millisekunnin kestäviä käskyjä mittausten lukumäärä on suuri ja mitattaessa yli sata
# sekuntia kestäviä käskyja mittausten lukumäärä on yksi.
#
# mitattavan käskyn on parasta antaa kirjoittaa näytölle. Mittaamisen aikana tietokoneen kanssa ei saa tehdä muuta.

function nolla () { : ;}

function mittaus () {   alkuhetki=$(date +%s.%N)   # echo '1 2 3 4' | awk '{print $2}'  # echo '1 2 3 4' | cut -d ' ' -f 2 # tr -dc 3 < koe | wc -c
  for (( n=1; n<=$mittauskerrat; n++ )); do { echo a ; sleep 5 ;} #  ajoitettavan kaikki tulosteet menevät lattian alle kun lisää ajoitettavan perään: 2&>/dev/null
done ;}
 
# Pääohjelma
alkuhetki=$(date +%s.%N)
mittauskerrat=1; mittaus; aika=$(echo $(date +%s.%N)-$alkuhetki-.0000055 | bc )
mittauskerrat=$(echo 1000/$aika+1 | bc ); mittauskerrat=$(echo ${mittauskerrat#[-+]}); (( $mittauskerrat > 100000 )) && mittauskerrat=100000; lisamittausaika=$(echo $aika*$mittauskerrat | bc )
alkuhetki=$(date +%s.%N)
(( $mittauskerrat > 0 )) && echo 'Lisämittauksia tullaan suorittamaan noin:'$lisamittausaika' sekuntia'
for (( n=1; n<=$mittauskerrat; n++ )); do # n:än arvo määrää mittausten lukumäärän ja skripti itse määrää se arvon. 5.00208052080000000000
  mittaus
done
echo $mittauskerrat':mittauksella saatu yhden mittauksen keskimääräinen aika sekunneissa= '$(echo $(date +%s.%N)/$mittauskerrat-$alkuhetki/$mittauskerrat-5.00174 | bc -l) | tee -a /tmp/lukemat

Tuloksien tarkistaminen käsin on teoriassa helppoa mutta siinä on kauhea työ. Esimerkiksi echo-käsky:
anna peräkkäin käskyt: time echo a; time echo aa;time echo aaa; ... ja pistä muistiin monenko a:n kohdilla user-aika muuttuu 0.000:sta 0.001:een ja edelleen 0.002:een.
- aika/merkki lasketaan: 0.001/((a-kirjainten luku kohdassa 0.002)-(a-kirjainten luku kohdassa 0.001))     
- echo:n kutsumiseen kuluva aika (aika: echo a) on: ((a-kirjainten luku kohdassa 0.002)-(a-kirjainten luku kohdassa 0.001))/2*(yhden merkin tulosdtukseen kuluva aika eli edellinen tulos)
- likimääräisesti oikean paikan voi etsiä tämäntyyppisesti: merkkijono=$( printf "%$(echo 6300)s" | tr ' ' 'a'); time echo $merkkijono
- tai jos epäilee että tulostuva merkki vaikuttaa: merkkijono=$(cat /dev/urandom | base64 | head -c 6300); time echo $merkkijono

Siis tälläkertaa: muutokset tapahtuivat kohdilla 1915 ja 6300. Näistä laskettuna aika/merkki on 0.16mikrosekuntia ja echon kutsumiseen kuluva aika on .205millisekuntia - siis tuo minun skriptini ilmoittaa tuon pitemmän ajan elikä .205millisekuntia.
- ei tämä vielä ihan oikein ole mutta likimääräisesti se on. Kunnon mittauksen arvoihin voi luottaa paremmin.
**
Taas tuli uutta tietoa: tuo mittaus-funktion "sleep 0.001" on täysin riittämätön ja sen tilalle täytyy laittaa "sleep 5".
Tämä taas aiheuttaa sen että mittauksia tehdään kovin vähän ja harvakseen joten mittausaikaa täytyy myös säätää: uusittu mittaus kestää noin 17 minuuttia.
- mutta samassa yhteydessä selvisi, että tuo date antaa tosiaan tarkan ajan mikä käskyn suorituksessa kuluu joten sen antamia tuloksia voi keskiarvoistaa.
- eihän tuo keskiarvoistaminen muuta sitä tosiasiaa että sama käsky voi ääritapauksina toisinaan kestää millisekunnin ja toisellakertaa 10millisekuntia. Tämä taitaa johtua siitä että BASH on keskeytys-prioriteetiltaan kasan pohjimmainen.
- mutta nyt on mahdollista tutkia mitä olisi tehtävissä tuon pitkän odotusajan lyhentämiseksi ja se kertoisi kuinka skripteihin saa jämäkkyyttä.
- myös skriptin koodi on päivitetty.
**
cachet siis ovat yksi syy miksi käskyjen tarkka ajoittaminen vaatii pitkiä odotusaikoja. Linuksissa on käsky joka nollaa sellaiset cachet joissa ei ole mitään sellaista jota ei kovalevyltä löytäisi. Mutta sen laittaminen käskyjen ajoittamiseen ei ole hyvä idea sillä tuo käsky kestää milloin mitäkin, yleensä kuitenkin millisekunteja. Seuraava käsky käytääkin menetelmää jossa tuon cachejen tyhjennykseen menevä aika lasketaan jokakierroksella ja vähennetään siitä ajasta joka pitäisi odottaa. Käsky ja sen kutsu ovat seuraavat:

Koodia: [Valitse]

function torku () { alku=$(date +%S%N); sudo /sbin/sysctl vm.drop_caches; loppu=$(date +%S%N); sleep $(echo "($1-($loppu-$alku))/1000000000" | bc -l) ; }; sudo echo; time torku 100000000
jossa torkkuaika annetaan nanosekunneissa. Eihän torkku-aika ole edes yhtä tarkka kuin sleep-käskyssä mutta siitä ei ole kysymyskään sillä käskyllä haetaan vakautta tuolta drop_caches:ilta.
- huomenissa alan kokeilla tyhjentääkö tämä oikeat cachet.
- eipä tämä cachejen tyhjentäminen vaikuttanut.
- muuten taitaapa olla niin että käskyjen suoritusaika on aivan erilainen kun ne annetaan päätteeltä tai skriptistä; skriptistä ne toimivat paljon nopeammin.

[nm]

Tämä liittyy aika-mittauksien keskiarvonmuodostukseen; tulokset ovat joskus aivan vääriä. Tai sitten ei, en minä tajua.

Käske: time echo *   . User-aika on jotakin. Anna uudestaan käsky: time echo *   . Aika on nyt nolla
- toisella kerralla * on ratkaistu, joten sen arvot vain haetaan jostain ratkaistussa muodossa?
- mutta cachejen, bufferien tai hash-taulujen nollaaminen ei vaikuta joten tässä ei ehkä ole koko totuus.

Voiko olla niin että echo:n ohjelma-koodi on jostai syystä tippunut BASH:ista pois? Ihan kuin kone bootin jälkeen hakisi koodinsa kun sitä ensimmäisen kerran käytetään.

echo *:n tapauksessa ensimmäisen suorituskerran viive johtuu todennäköisesti levyoperaatioista (lähinnä hakuajasta), kun järjestelmä joutuu lukemaan kiintolevyltä hakemiston sisällön. Seuraavilla suorituskerroilla tarvittavat blokit ovat levyvälimuistissa (jota kerneli säilyttää keskusmuistissa, prosesseilta vapaaksi jääneessä tilassa). Sieltä tieto löytyy paljon nopeammin.

Tämä on huomioitava yleensäkin mitattaessa ohjelmia, jotka lukevat levyltä. Kiintolevyn hitaus vaikuttaa tulokseen ensimmäisellä suorituskerralla, mutta seuraavilla suorituksilla levyvälimuisti voi nopeuttaa ohjelman toimintaa huomattavasti.

[_Pete_]

Asiaan liittyen:

http://www.shibuvarkala.com/2009/04/howto-enable-process-accounting-in.html

Tuolla tapaa saisi tarkkoja lukemia prosessien vimeistä cpu/muista ajoista ...

[Postimies]

Itselle on hyvin riittänyt time make -j4 ja saa suunnilleen tietää kauanko kesti. Toinen kerta menee aina nopeammin kun kaikkea ei enää käännetä ja suurin osa löytyy muistista. Ero voi olla iso. Tai sitten ensimmäinen kerta ei onnistu. Eikä toinenkaan. Koneen kuorma vaikuttaa kovasti suoritusnopeuteen. Itse sain tänään muistin niin täyteen ja kuorman ylös, että näppäimmistön luku kesti kauan. Pienet luvut ovat ongelmallisia tietokoneissa (lähellä 0). Parempi käyttää laskuissa kokonaislukuja tai ainakin tarkistaa riittääkö tarkkuus.