[.NET] Nauwkeurig meten van code execution time op UI thread

[NickThissen]

In mijn applicatie kunnen gebruikers hun eigen scripts schrijven, welke ongeveer 30 keer per seconde uitgevoerd worden. De scripts moeten noodzakelijk op de UI thread uitgevoerd worden omdat ze direct met de UI moeten communiceren. Het is de bedoeling dat de scripts zeer simpel en snel zijn zodat er geen "lag" in de UI optreedt. Dat wil zeggen een paar regels code om een getal naar een string te converteren, kleur van een object te veranderen, positie van een object te veranderen, etc.

Ik wil de gebruiker graag nauwkeurige feedback geven over hoe lang het script nodig heeft om uit te voeren. Als ze dan lag merken weten ze welk script ze moeten verbeteren.

Momenteel doe ik dit met een Stopwatch, de manier die ik op letterlijk elk topic op het internet kan vinden:

C#:

var sw = new Stopwatch();
sw.Start();
ExecuteScript();
sw.Stop();
ReportExecutionTime($"Elapsed: {sw.ElapsedTicks/10d} us");

Dit werkt prima, op een groot probleem na: als de UI iets anders aan het doen is (dat compleet ongerelateerd kan zijn aan de scripts) en enige tijd nodig heeft, dan is die tijd terug te zien in de execution time van de scripts. Stel dat de gebruiker een knop indrukt welke op de achtergrond een file leest ofzo, dit duurt toch al gauw weer een paar ms en de script execution time schiet enorm omhoog (van enkele microseconden tot ~milliseconden).

Ik kan niet helemaal verklaren waarom dit zo is aangezien de stopwatch toch echt enkel de ExecuteScript method zou moeten timen? Maar het is zeer irritant omdat om de haverklap de scripts heel traag lijken te lopen, ook al had het niks met het script te maken maar met iets compleet anders.


In een simpele test applicatie kan ik het probleem eenvoudig reproduceren:
- Een continue loop op een background thread met 250ms sleep
- Elke iteratie roept de loop een method op de UI thread aan die een 10 ms sleep doet (om een script na te doen)
- Een knop welke een seconde sleep doet, om een ongerelateerd iets na te bootsen wat flink wat tijd kost.

C#:

        public MainWindow()
        {
            InitializeComponent();

            var t = new Thread(Loop);
            t.Start();
        }

        private void Loop()
        {
            while (true)
            {
                var sw = new Stopwatch();
                sw.Start();
                Dispatcher.Invoke(WorkOnUiThread);
                sw.Stop();
                Debug.WriteLine($"Elapsed: {sw.ElapsedMilliseconds:0.0} ms");

                Thread.Sleep(250);
            }
        }
        
        private void WorkOnUiThread()
        {
            Thread.Sleep(10);
        }

        private void Button_Click(object sender, RoutedEventArgs e)
        {
            Thread.Sleep(1000);
        }

Zolang ik de knop niet aanraak duurt de "WorkOnUiThread" ongeveer 10 ms (af en toe kleine uitschieters). Zodra ik op de knop klik duurt de eerstvolgende iteratie ongeveer 800 ms (ik gok: 1 sec - 250 ms?).


Hoe kan ik de tijd van enkel de WorkOnUiThread method nauwkeurig timen, zelfs als de UI door iets anders tijdelijk vast loopt? Is dit uberhaupt mogelijk?

[FoOnEeN]

Volgens mij moet je die stopwatch laten lopen op de thread die je wil meten. Nu krijg je het probleem dat de uitvoer van die thread niet altijd voorrang krijgt en dus moet wachten omdat de processor bezig is met andere hogere prio threads af te handelen. Ondertussen loopt je stopwatch op de ui thread door. Als je de stopwatch verplaatst naar de uitvoerende thread krijg je al betere resultaten, echter weet ik niet precies hoe die stopwatch uitvoer meet.

[farlane]

Die stopwatch meet de tijd die verstreken is tussen de Start() en de Stop(), dus ook de tijd waarbij niet de script-thread maar een andere thread actief was. Jij wilt CPU tijd weten, maar de Stopwatch meet "wall clock tijd"

Bekijk deze maar es : https://www.codeproject.c.../31152/ExecutionStopwatch

[ Voor 34% gewijzigd door farlane op 15-11-2017 16:27 ]

[NickThissen]

Poeh, ik snap het even niet meer.

Jullie hebben natuurlijk helemaal gelijk dat de stopwatch in de zelfde thread moet. De test applicatie klopt dus inderdaad niet, en als ik de stopwatch verplaats dan meet hij elke keer precies 10 ms dus kan ik het probleem niet reproduceren.

In mijn echte applicatie staat de stopwatch echter wel op de goeie plek (dus binnen de Dispatcher.Invoke). En daar kan ik het wel reproduceren...

Ik zal eens kijken naar die ExecutionStopwatch, misschien helpt dit, dank!

[whoami]

Ik zou eigenlijk verwachten dat die Invoke een blocking operatie is, en als die Action op de UI thread wordt uitgevoerd, er dus geen andere acties op de UI thread kunnen uitgevoerd worden, dus, dat je dan ook niet op die button kunt klikken.

[NickThissen]

De ExecutionStopwatch lijkt zeer onnauwkeurig (~15 ms windows limiet). Ik zoek microseconden nauwkeurigheid, 10 ms execution is natuurlijk enorm lang als dit 30 keer per seconde moet uitvoeren.

whoami schreef op woensdag 15 november 2017 @ 16:36:
Ik zou eigenlijk verwachten dat die Invoke een blocking operatie is, en als die Action op de UI thread wordt uitgevoerd, er dus geen andere acties op de UI thread kunnen uitgevoerd worden, dus, dat je dan ook niet op die button kunt klikken.

Ja dat klinkt logisch...

Echter snap ik nu niet wat ik in de daadwerkelijke applicatie zie. De scripts die ik uitvoer als test zijn allemaal "leeg". Het zijn C# scripts die met Roslyn compiled worden, dat levert een object op welk een interface implementeert, en daarop kan ik 30 keer per seconde de Execute method aanroepen.

De Execute method in alle scripts ter test is momenteel niks anders als:
return null;

Als ik dit test dan krijg ik execution tijden van 5-7 microseconden. Klinkt redelijk voor een leeg script denk ik. Maar dan ineens schiet hij tot 3000 microsec... En het lijkt vaak te correleren met als ik iets anders in de UI aan het doen ben.

Ik snap dat dit zonder code niet te begrijpen is maar de code kan ik echt niet zomaar ff samenvatten, dat is veel te veel... Ik ga proberen of ik het kan reproduceren op een andere manier.

[Gomez12]

Wat ik vermoed is dat je het in je TS het meest juist omschrijft.

Het zal waarschijnlijk idd voornamelijk optreden bij file-acties etc. Die zijn namelijk redelijk blocking voor je hele OS. Als er iets van de HDD gelezen moet worden dan stopt je hele OS even.

Vroeger (heb geen cd-speler meer in mijn computers) kon je dit prachtig nabootsen door continue de muiscursor te bewegen zodat die in beweging blijft en dan een cd in de cd-speler te doen en die dicht te doen, dan ging je muis even schokken omdat je hele OS gewoon bezig was met het afhandelen van interrupts vanuit I/O.

Hier is simpelweg niets aan te doen, omdat een computer / OS geen perfecte multithreading kent. Je zit met enkele meldingen simpelweg met meet-fouten.
Ik zou gewoon 100 metingen middelen en dan dat getal bekijken.

Als je het echt op basis van 1 meting van < 20ms wilt doen dan ga je tegen een heel scala aan problemen aanlopen. Bijv bij gevirtualiseerde hardware wordt er continue de tijd gesynched omdat een andere gevirtualiseerde machine kan zorgen (bijv bij 100% belasting) dat jij enkele clockticks mist.
Maar ook bij Remote Desktop / Citrix draaien van applicaties zitten er wat geintjes in met ms timings vanwege netwerk lag etc.
Daarnaast heeft .Net standaard een jit-compiler, oftewel als jij iets in je applicatie aanklikt wat nog niet jit-gecompiled is, dan staat je UI-thread ook even stil totdat die nieuwe functionaliteit gecompiled is.

Sowieso zijn .net en java slechte talen als het echt op accurate timings aankomt, daarnaast is windows niet al te geschikt voor accurate timings.
Het is voor de meeste mensen / applicaties simpelweg niet nodig om accuraat te zijn op ms niveau.
Het kan wel, maar het vereist heel wat omwegen. Terwijl je volgens mij voor jouw doel ook kan volstaan met simpelweg gemiddelde tijden die simpel te krijgen zijn.

Let wel dat alles wat ik hier beschrijf van toepassing is voor wijzigingen van 5-100 microseconden, hoe jij aan verschillen van 3000 komt is weer iets anders.

[farlane]

Jullie hebben natuurlijk helemaal gelijk dat de stopwatch in de zelfde thread moet.

Neen, dat is niet wat ik heb gezegd, en ook niet wat het probleem is : je meting zit in al dezelfde thread, daar ligt het niet aan.

NickThissen schreef op woensdag 15 november 2017 @ 16:47:
De ExecutionStopwatch lijkt zeer onnauwkeurig (~15 ms windows limiet). Ik zoek microseconden nauwkeurigheid, 10 ms execution is natuurlijk enorm lang als dit 30 keer per seconde moet uitvoeren.

Tja, dat is de tick van de scheduler ben ik bang. (Zie ook hier http://blog.kalmbachnet.de/?postid=28)
Misschien dat je met QueryThreadCycleTime iets kunt doen, maar die returned CPU cycles en geen tijdseenheid.
Zie ook hier interessante weetjes over Stopwatch : http://blog.kalmbachnet.de/?postid=28

Als ik dit test dan krijg ik execution tijden van 5-7 microseconden. Klinkt redelijk voor een leeg script denk ik. Maar dan ineens schiet hij tot 3000 microsec... En het lijkt vaak te correleren met als ik iets anders in de UI aan het doen ben.

Dat is toch logisch? Je meet met je stopwatch al die dingen die er gebeuren tussen het starten en stoppen van de stopwatch, dus ook het afhandelen van UI messages. Dus als je thread door een andere thread (met hogere prioriteit bv) wordt weggeparkeerd dan meet je ook de tijd die die thread actief is geweest.

[ Voor 15% gewijzigd door farlane op 15-11-2017 20:57 ]

[RobIII]

Gomez12 schreef op woensdag 15 november 2017 @ 20:11:
Het zal waarschijnlijk idd voornamelijk optreden bij file-acties etc. Die zijn namelijk redelijk blocking voor je hele OS. Als er iets van de HDD gelezen moet worden dan stopt je hele OS even.

In 1834 misschien Toen je nog geen fatsoenlijk multitasking OS had en alles door je CPU heen hobbelde (PIO). Dat is sinds (U)DMA al lang niet meer aan de orde.

[ Voor 21% gewijzigd door RobIII op 15-11-2017 21:01 ]

[Gomez12]

RobIII schreef op woensdag 15 november 2017 @ 20:54:
[...]

In 1834 misschien Toen je nog geen fatsoenlijk multitasking OS had en alles door je CPU heen hobbelde (PIO). Dat is sinds (U)DMA al lang niet meer aan de orde.

Kan je misschien ook nog ergens onderbouwen waarom het "al lang" niet meer aan de orde is? Want je wikipedia linkjes zeggen namelijk dat het nog steeds aan de orde is enkel minder.

En kan je dan ook nog even een linkje geven naar een fatsoenlijk multitasking OS wat .Net draait.
Want ik ken geen realtime multitasking OS wat fatsoenlijk mono of .Net draait, alleen enkele near-realtime OS'en.

[farlane]

Gomez12 schreef op woensdag 15 november 2017 @ 23:20:
Als er iets van de HDD gelezen moet worden dan stopt je hele OS even

Op welk moment "stopt het OS even" dan?

[NickThissen]

Zullen we ontopic blijven?

farlane schreef op woensdag 15 november 2017 @ 20:47:
[...]

Dat is toch logisch? Je meet met je stopwatch al die dingen die er gebeuren tussen het starten en stoppen van de stopwatch, dus ook het afhandelen van UI messages. Dus als je thread door een andere thread (met hogere prioriteit bv) wordt weggeparkeerd dan meet je ook de tijd die die thread actief is geweest.

Ik snap nog niet waarom dit logisch zou zijn. Als ik zowel het start/stop van de stopwatch, als de code die ik wil timen, allemaal op de UI thread draai, wat kan er dan nog tussendoor komen dat de stopwatch gaat meten wat niet te maken heeft met de code die tussen de start en stop staat?

Stel dat het programma (of zelfs een ander programma?) een file gaat lezen, gaat dit op een andere thread dan de UI en krijgt deze meer prioriteit, en is dat een manier waarop ik meer kan meten dan ik wil? Als dit zo is, dan blijft mijn vraag nog steeds hetzelfde: hoe kan ik nauwkeurig meten hoe lang enkel mijn eigen code duurt (de code tussen de start en stop) zonder dat andere ongerelateerde dingen de tijd langer laten lijken?


Om Gomez te antwoorden over middelen; middelen is sowieso een goeie optie maar is erg lastig in mijn applicatie omdat het dus scripts zijn die de gebruiker schrijft. Ten eerste hoeft een script niet perse elke "update" (30 keer per seconde) uit te voeren (de meeste wel, maar hoeft niet), ten tweede kan een script de ene keer langer nodig hebben dan de andere keer (omdat er een andere conditie waar is, whatever). Dit wil ik niet middelen, ik wil juist de gebruiker laten zien wanneer er af en toe een uitvoer is waarbij het te lang duurt.

[ Voor 18% gewijzigd door NickThissen op 16-11-2017 09:40 ]

[AtleX]

Kan je niet beter je scriptjes op losse threads uitvoeren en eventuele UI updates doen door middel van een Dispatcher? Als je Dispatcher.CurrentDispatcher vanuit de UI thread meegeeft aan je scripts kunnen ze daarmee los.

[NickThissen]

Ik zal er eens over nadenken. Eerlijk gezegd zie ik het niet zitten om de gebruikers met dispatchers te laten gaan werken, de meeste krijgen het nog net voor elkaar om een float naar een string om te zetten, als ik hun threading uit moet gaan leggen dan komt het niet goed

Sowieso wil ik de hele update logica gaan verbeteren zodat alles behalve de UI update naar de background thread gaat, maar dat is nog even te ver weg en te veel omschrijven.

Uiteindelijk wil ik nog steeds nauwkeurig kunnen meten hoe lang de scripts duren (ook al draaien ze op de achtergrond, als een script een halve seconde nodig heeft dan is dat zeker niet goed).

[ThomasG]

Je zou dit met de native GetThreadTimes functie kunnen doen. Dit berekend exact hoeveel tijd de thread heeft gelopen, zonder de tijd dat de thread sliep.

[NickThissen]

ThomasG schreef op donderdag 16 november 2017 @ 09:58:
Je zou dit met de native GetThreadTimes functie kunnen doen. Dit berekend exact hoeveel tijd de thread heeft gelopen, zonder de tijd dat de thread sliep.

Dat heb ik al geprobeerd (dit zat ook in de ExecuteStopwatch hierboven al geplaatst) maar die is lang niet nauwkeurig genoeg helaas.

[Radiant]

Je gaat het, als je de slaaptijd niet wil meenemen, ook niet veel nauwkeuriger krijgen. Als je GUI niet responsive genoeg is moet je je aanpak veranderen en asynchroon gaan werken, maar dat is al gezegd.

De nauwkeurigste, meest real-time timer die je kan vinden is een multimediatimer, maar die loopt door na een context switch. Je moet dit gewoon niet willen op een normaal OS met preemptive multitasking.

[RobIII]

NickThissen schreef op donderdag 16 november 2017 @ 09:46:
Eerlijk gezegd zie ik het niet zitten om de gebruikers met dispatchers te laten gaan werken

Ik zou 'm dan ook niet, zoals gesuggereerd, meegeven maar juist de gebruikers een functie bieden om de UI bij te werken waarin je zelf het hele dispatcher gebeuren stopt zodat gebruikers zich daar niet om hoeven bekommeren.

Gomez12 schreef op woensdag 15 november 2017 @ 23:20:
Kan je misschien ook nog ergens onderbouwen waarom het "al lang" niet meer aan de orde is? Want je wikipedia linkjes zeggen namelijk dat het nog steeds aan de orde is enkel minder.

En kan je dan ook nog even een linkje geven naar een fatsoenlijk multitasking OS wat .Net draait.
Want ik ken geen realtime multitasking OS wat fatsoenlijk mono of .Net draait, alleen enkele near-realtime OS'en.

Ik wil die discussie best voeren maar niet nu (te moe ) en niet hier (offtopic). Maar ik denk dat jij en ik allebei weten dat 't dan vooral insectencopulatie wordt en geneuzel over semantiek "Alles" "staat even stil" wanneer een (ander) proces even "z'n werk doet". Een CPU kan (per "core") natuurlijk altijd maar "één ding" doen. En zo kan ik nog wel even doorgaan met vanalles-en-nogwat in quotes zetten zonder al die dingen in al hun nuances te moeten kwalificeren of ergens op kunnen worden afgerekend. Mijn hele punt is dat, in the grand scheme of things, zaken helemaal niet (meer) "stil staan" zoals ze dat "vroeger" deden; daar mag je het mee oneens zijn, maar je implicatie waar ik oorspronkelijk op reageerde vond (en vind) ik schromelijk overdreven en eigenlijk niet (echt) relevant voor dit topic. Let alone de "(near-)realtime multitasking OS's" discussie die ook enkele uren, at best, zal toevoegen aan het geheel. Ik denk dat 't verstandig is dit konijnenhol niet in te gaan en 't houden op 'agree to disagree', kee?

[__fred__]

Dispatcher.Invoke laat een stuk code uitvoeren op de UI thread door middel van een message die moet worden opgevangen door de message loop. Als je vervolgens je UI thread suspend, of iets langdurigs laat uitvoeren, dan loopt de message loop niet en wordt je dispatcher.invoke niet geprocessed.

Als je het al zo wilt doen, dan zou ik alle code op de UI threads asynchroon maken. Asynchrone code (async/await) geeft de controle terug aan de caller, i.p.v. te suspenden als er een langdurige operatie loopt. De caller kan dan gewoon lekker de message loop blijven uitvoeren.

Gevolg is wel dat al je onderliggende code async/non-blocking moet zijn. Blocking code moet je encapsulaten en op backgroundthreads uitvoeren.

[farlane]

NickThissen schreef op donderdag 16 november 2017 @ 09:37:
Ik snap nog niet waarom dit logisch zou zijn. Als ik zowel het start/stop van de stopwatch, als de code die ik wil timen, allemaal op de UI thread draai, wat kan er dan nog tussendoor komen dat de stopwatch gaat meten wat niet te maken heeft met de code die tussen de start en stop staat?

Van alles, zelfs de bakker kan langskomen als je OS heeft besloten dat de bakker belangrijker is dan jouw thread.

Stel dat het programma (of zelfs een ander programma?) een file gaat lezen, gaat dit op een andere thread dan de UI en krijgt deze meer prioriteit, en is dat een manier waarop ik meer kan meten dan ik wil?

Een file lezen zal voor het OS vaak een punt zijn waar het OS weer switched naar een thread die niet op I/O wacht.

Als dit zo is, dan blijft mijn vraag nog steeds hetzelfde: hoe kan ik nauwkeurig meten hoe lang enkel mijn eigen code duurt (de code tussen de start en stop) zonder dat andere ongerelateerde dingen de tijd langer laten lijken?

Als GetThreadTimes niet nauwkeurig genoeg is voor je zou je naar QueryThreadCycleTime kunnen kijken zoals ik al aangaf.
Een alternatief is te zorgen dat er zo min mogelijk andere processen/threads zijn die processortijd vragen, of te zorgen dat jouw thread de hoogste/de hoogste mogelijke prioriteit heeft.

Dat gezegd hebbende, de kans dat je timing dichter bij de waarheid komt loopt op op het moment dat je dat wat je wilt timen de enige activiteit is op zijn thread. Op een multiprocessor systeem is de kans dat een script (dat niet al te lang is) gewoon zijn volle timeslice gebruikt en niet tussendoor weggeswitched wordt.

In jouw geval betekent dat dat je het script juist *niet* op de UI thread wilt doen, want daar gebeurt nog veel meer dan alleen het uitvoeren van je script.

[pedorus]

Vervang Invoke door InvokeAsync en het gaat veel sneller Waarom zou je precies moeten wachten op het resultaat van die Invoke? Dit is een beetje afhankelijk van wat je daar doet natuurlijk, maar op een statusupdate hoef je niet te wachten.

[__fred__]

pedorus schreef op donderdag 16 november 2017 @ 23:45:
Vervang Invoke door InvokeAsync en het gaat veel sneller Waarom zou je precies moeten wachten op het resultaat van die Invoke? Dit is een beetje afhankelijk van wat je daar doet natuurlijk, maar op een statusupdate hoef je niet te wachten.

Misschien omdat hij de tijd die WorkOnUiThread duurt wil meten? Dan kun je maar beter erop wachten.