Graffremstilling af underlig opførsel for IO

Dato:	18 Mar 2014
Varighed:	7 timer

Status

Computer og tand er ordnet efter nedbrud af begge

Grafgenerator-kode er lavet, men der er ingen blog over arbejdet (pga. computer-nedbrud)

Indledende data-opsamlig er påbegyndt.

Opsamling af arbejder uden blog

Kode til at generere grafer over den data der opsamles, er lavet[1]. Koden er ikke testet grundigt, da data-opsamlings format ikke er helt fastlagt.

Mål 

Færdigør den indledende undersøgelse af hvad der sker med trådene, samt generer grafer over dataen. Dette indbefatter at have fastlagt en måde hvorpå data skal gemmes.
Opsæt ordenlig backup af støtteprojekter.

Data-opbygning

Data gemmes som tekst-strenge under afviklingen af programmet. I første omgang gemmes dataen i hukommelsen, for så når programmet er afsluttet, at blive skrevet til disken. Hver logging af data skrives i følgende format:

startTid,slutTid,adfærdNavn

Start og slut indikerer hvilket ms dette log-event blev start og sluttet. Disse tal er ift. start af log-klassen, men behandles af GrafGeneratoren således, at alle tidsangivelser bliver tilpasset således, at første registrede tid er ved 0.

Adfærdens navn er enten den adfærd der har været aktiv eller Arbitratoren.

Hver gang der skrevet til loggen, registreres navn og startTid (T1) og dette logEvent registreres som det seneste. Det logEvent, hvis der er noget, der var umiddelbart inden dette nye seneste, får sat slutTid til T1. Bliver en adfærd faktisk færdig med sin action, så registreres slutTid til dette sluttidspunkt.

Interrupt_Subsumption-Data[2]

Herunder er kun vist den graf der blev opbygget af en kørsel med leJOS-styrring (også kaldet interrupt andre steder på bloggen).

Denne video er opførslen af robotten for den data der er ovenfor i grafen. Dog passer tiden i videoen ikke helt overens med tiden i grafen!

Jeg har valgt at registre hvilket valg arbitratoren træffer hver gang den køres. Derfor er SUPPRESS, NEW og NO_CHANGE skrevet i parantes. New betyder at der ikke var nogen anden adfærd aktiv, da arbitratoren startede en adfærd. No_change betyder at den nuværrende adfærd ikke blev ændret og Suppress betyder at en kørende adfærd blev undertrykt for at starte en ny adfærd.

Jeg har forsøgt at gemme til loggen inden en adfærd begynder, samt umiddelbart inden hver gang en adfærd forsøger at vente/sove. For Arbitratoren gemmes der blot hver gang en beslutning er taget om hvilken adfærd der skal være aktiv.

IO_Subsumption-data[3]

Herunder er så hele grunden til testen: Dataen for hvordan trådene bliver færdig med at opdatere deres motor-kommandoer. Først en video der dokumenterer hvordan robotten opfører sig:

Herunder er så graferne der skal forsøge at beskrive hvad der sker:

Den første observation jeg gjorde mig, er at der opsamles over 60 gange så mange logEvents for IO som for Interrupt, 35340 vs 578. Korrigeret for forskellen i tid er det dog "kun" en faktor 14 til forskel i hvor mange gange der logges. Den næste er naturligvis at SeekBall ser underligt anderledes ud end de andre.

Jeg ser i første omgang bort fra forskellen i logEvents. Alle tests jeg har lavet med logging slået til passer fint overens med de samme test på robotten uden logging; dvs. IO performer tilfældigt og Interrupt fungerer nogenlunde som forventet, omend ikke optimalt.

SeekBall logEvents er rigtig interessant og derfor har jeg lavet et udsnit af dataen til en ny graf. Jeg har valgt at tage perioden fra 16000-18000, da programmet ser ud til at være "stabiliseret" på dette tidspunkt.

Problemet er jo helt klart at der går næsten 2 sekunder imellem to opdateringer af motor-kommandoer fra SeekBall. Dette kommer som en klar overraskelse for mig, da koden der afvikles ikke er specielt kompleks: >=, <, addition, multiplikation samt et enkelt cast (int).

Dette mysterie må være en undersøgelse i sig selv, til senere.

Anden sammenlignings-data

Jeg har også samlet noget data over hvordan IO vs Interrupt ser ud. Herunder ses lidt information, hvor jeg prøvede at danne mit et billede af hvor stort tidsspænd hvert LogEvent dækker over:

IO

Min   duration: 0 ms

Max   duration: 490 ms

Avg   duration: 1 ms

Total duration: 70296 ms

Interrupt

Min   duration: 1 ms

Max   duration: 713 ms

Avg   duration: 27 ms

Total duration: 16154 ms

Konklussion på data

Umiddelbart begynder jeg at tænke at det kunne være rart at tilføje mere CPU-power for at se om dette ville løse mine problemer med trådene (jf. den artikkel jeg arbejder frem fra). Dette er dog af åbenlyse årsager ikke muligt for min robot. En anden ide kunne være at pille ved trådenes prioritet. F.eks. får dribble en hel del cpu-tid til at gå med ikke at ændre noget ved robottens makro-opførsel. Fra tidligere blog ved jeg dog at dette ikke kan lade sig gøre...

Til fremtidig test og undersøgelse af problematikken ved IO_Subsumption må trådningen derfor være en central problemstilling, der skal løses for at kunne få adfærdskontrollen til at fungere overhovedet.

References

1. https://sites.google.com/site/digikaison/GrapgGeneratorV1.tar.gz

2. https://sites.google.com/site/digikaison/leJOS_Log_6.txt

3. https://sites.google.com/site/digikaison/IO_Log_4.txt