Hello Everyone
I have a driver which runs on XP SP3, that requires high performance, so I try to keep to ISRs and DPCs and short as possible. The typical ISR time is 10 microsecs. When I hit Windows Start button I suddenly get a long ISRs (1000 to 2500 microsecs). I run tracelog but could not find other driver to blame. I got 40 long ISRs, 31 of them were mine and 9 were of videoprt.sys. Both driver have the same IRQL and no other driver has such a long ISRs. I can understand that Windows XP isn’t real time system, but according to my short device drivers development experience, I could not find the cause.
I saw the same phenomenon when right clicking on an area which causes a context menu to appear.
BTW: is there a tool that can analyze ETL file and shows a graphic time line of all traced events (ISRs and DPCs)?
Thanks,
Tal
Have you tried using xperf to visualize what’s happening the trace file?
-p
-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@yahoo.com
Sent: Friday, September 09, 2011 1:37 PM
To: Windows System Software Devs Interest List
Subject: [ntdev] Performance Issues - Long ISRs
Hello Everyone
I have a driver which runs on XP SP3, that requires high performance, so I try to keep to ISRs and DPCs and short as possible. The typical ISR time is 10 microsecs. When I hit Windows Start button I suddenly get a long ISRs (1000 to 2500 microsecs). I run tracelog but could not find other driver to blame. I got 40 long ISRs, 31 of them were mine and 9 were of videoprt.sys. Both driver have the same IRQL and no other driver has such a long ISRs. I can understand that Windows XP isn’t real time system, but according to my short device drivers development experience, I could not find the cause.
I saw the same phenomenon when right clicking on an area which causes a context menu to appear.
BTW: is there a tool that can analyze ETL file and shows a graphic time line of all traced events (ISRs and DPCs)?
Thanks,
Tal
NTDEV is sponsored by OSR
For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars
To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
XPerf will not install on XP and unfortunately things like ISR and DPC
profiling will only work on Vista and higher. Try to install your driver on
a Vista or Windows 7 system if possible and run LatencyMon or Xperf if you
prefer. If this is not an option what you need is probably RattV3 for XP.
//Daniel
wrote in message news:xxxxx@ntdev…
> Hello Everyone
>
> I have a driver which runs on XP SP3, that requires high performance, so
> I try to keep to ISRs and DPCs and short as possible. The typical ISR time
> is 10 microsecs. When I hit Windows Start button I suddenly get a long
> ISRs (1000 to 2500 microsecs). I run tracelog but could not find other
> driver to blame. I got 40 long ISRs, 31 of them were mine and 9 were of
> videoprt.sys. Both driver have the same IRQL and no other driver has such
> a long ISRs. I can understand that Windows XP isn’t real time system, but
> according to my short device drivers development experience, I could not
> find the cause.
>
> I saw the same phenomenon when right clicking on an area which causes a
> context menu to appear.
> BTW: is there a tool that can analyze ETL file and shows a graphic time
> line of all traced events (ISRs and DPCs)?
>
> Thanks,
> Tal
>
Thanks Peter and Daniel
Can I use XPref to analyze etl files generated on Windows XP?
Installing my driver on Windows 7 isn’t possible right now.
I’ve used RattV3, but as far as I can tell I has the same output as tracerpt has. It doesn’t show time line of events.
I thought of building such tool myself, and found this at MSDN
http://msdn.microsoft.com/en-us/library/aa964780(v=VS.85).aspx
It explains about the event type class for interrupt service routine (ISR) events, but I don’t see anything about the end of ISR time stamp. I’ll keep searching…
Thanks for your help,
Tal
So you suspect the video, and this is quite grounded, given what is known about video.
What model is the video card? Have you tried to tweak video settings
(acceleration, various effects such as menu animation, resolution?
–pa
Hi Pavel
I don’t have any evidences to suspect to video…
What I see is 40 long ISRs (1000 to 2500 microsecs) when I press the Windows ?Start? button. 31 of them come from my driver and 9 come from videoprt.sys. Both my driver and videoprt.sys have the same IRQL. According to what I understand, tracelog textual report shows the execution duration of ISRs and DPCs (the time it takes to execute it from start to end). So, once my ISR is running, videoprt.sys can not interrupt it (and even if it could, it can only explain part of the incidents).
To find the cause for long ISRs, I tried to find some other drivers with higher IRQLs that have:
- Long ISRs (and there are none)
- ISRs ?storms? (it seems that there are none, but it is hard to tell?)
- Long DPCs (maybe the IRQL is raised within the DPC)
Are there any other reasons for long ISRs?
I tried to find a tool that can parse the ETL file and show a time line of ISRs and DPCs but could not find one. Showing all the ISRs and DPCs of the trace session, can tell if some other ISRs or DPCs interrupted my ISR. I thought of parsing it myself, but I cannot understand how the end timestamp of ISR (or DPC), is calculated.
Of course, it is possible that the long ISR time is my driver?s fault. I?ll look at my ISR routine and try to find any reasons for it.
Thanks,
Tal
Hi Everyone
After disabling the audio device the problem solved.
My driver has an option of doing some I/O in the ISR. It works fine usually, but when I hit Windows “Start” button it results long ISRs (not only to my driver).
This is probably because windows tries to play some sound when you do that (it can be disabled throgh the cotrol panel) and it puts some load to the chipset (or some other system component).
Tal
On 11-Sep-2011 17:35, xxxxx@yahoo.com wrote:
Hi Everyone
After disabling the audio device the problem solved.
My driver has an option of doing some I/O in the ISR. It works fine usually, but when I hit Windows “Start” button it results long ISRs (not only to my driver).
This is probably because windows tries to play some sound when you do that (it can be disabled throgh the cotrol panel) and it puts some load to the chipset (or some other system component).
Tal
Hmm, so this is audio…
Can you tell what is the audio device’s IRQ?
The sound corresponding to the Start button is “Menu popup” (in Control
panel->Sounds). Do other system events with assigned sounds cause same
effects? (such as “navigation start”, “asterisk”) or when you just play
this sound in the control panel dialog, or play a song or video in media
player?
– pa
Hi Pavel
I tried to play some sounds with Media Player and it caused the same effects.
I’ll check about the IRQ. Why do you ask about the sound device IRQ? Are you interested in knowing other devices IRQs aswell?
Tal
wrote in message news:xxxxx@ntdev…
> Hi Pavel
>
> I tried to play some sounds with Media Player and it caused the same
> effects.
> I’ll check about the IRQ. Why do you ask about the sound device IRQ? Are
> you interested in knowing other devices IRQs aswell?
>
> Tal
Sorry, was distracted by those win8 rumors…
Is the sound card IRQ same as yours or different?
If same then every time you get interrupt the sound driver will check its
hardware, and v.v.
When any side does this wrong, bad things may happen, up to total machine
hang.
If the delays are indeed caused by sound device, you can try to find another
model
or tweak the one at hand (change its performance parameters if it has some).
Otherwise, disable it.
This exactly means “Windows is not a real time OS”.
What one gets with Windows depends on variety of hardware and software.
Regards,
–pa
Hi Pavel
According to what I see, my driver and the audio driver have different IRQs.
The problem is probably is system resource that is being busy.
My tweak was to disable the sound affects through Control Panel…
BTW: are you using tracelog.exe? I tried to decode its output but I can’t figure how does the ISR and DPC duration are calculated from it. I only saw start time for it…
Thanks,
Tal
To my knowledge it should not be able to measure ISR and DPCs execution
times using a kernel logger session on anything before Windows Vista…
However it is fairly trivial to measure your own ISR execution time in your
routine. And even if that may include time spent in other ISRs that
interrupt you it’s not that difficult to find out if it’s you causing the
problem. Excecuting normal CPU instructions should not be able to cause
significant delays (that is unless you are hitting CPU bugs). Reading to
device memory or registers can cause long delays due to hardware factors.
In order to find out if it’s your routine causing the latency and not
another routine interrupting you, you could even go as far as raising IRQL
to HIGH_LEVEL as a temporarily measure for the time your ISR runs. This way
you can make sure noone and not even the system clock will interrupt you so
you will get pure results. This may bugcheck the system if this blocks the
system from receiving a clock interrupt for too long but at least that’s an
indication that your routine is causing the problem. As an alternative you
could raise to just below clock level (CLOCK_LEVEL-1). You can use routines
like KeQueryPerformanceCounter or KeQueryInterruptTime to measure the
duration of your ISR.
To see if you may have a misbehaving driver sharing your interrupt vector,
With a debugger attached you can use the !idt command to find out.
You can use a utility like DpcLat to see kernel latency spikes appear in
real time. These can be caused by long ISRs, DPCs, otherwise misbehaving
drivers, faulty hardware, CPU bugs
or otherwise. While the utility does not reveal the root cause it can be a
useful tool for measuring and you can disable devices while it’s running to
see if the problem goes away or if they go away without your driver.
Good luck,
Daniel Terhell
Resplendence Software Projects Sp
xxxxx@resplendence.com
http://www.resplendence.com
wrote in message news:xxxxx@ntdev…
> Hi Pavel
>
> According to what I see, my driver and the audio driver have different
> IRQs.
> The problem is probably is system resource that is being busy.
> My tweak was to disable the sound affects through Control Panel…
>
> BTW: are you using tracelog.exe? I tried to decode its output but I can’t
> figure how does the ISR and DPC duration are calculated from it. I only
> saw start time for it…
>
> Thanks,
> Tal
>
> This exactly means “Windows is not a real time OS”.
Well, x86 platform in itself is not really suitable for real-time tasks (at least hard-RT ones) due to the possibility of SMI, which is totally transparent to the OS software. At the OS level, you don’t know what particular event/action triggers it; you cannot mask it; you cannot intercept it - it is a complete “terra incognita” to the OS software; it has the highest priority, and handling it can take hundreds of microseconds.
In the OP’s particular case, it may well happen that the OP’s hardware somehow triggers some chipset bug so that SMI gets raised in order to work around this bug. Taking into consideration otherwise unexplicably long delays in ISR, SMI is the very first thing that gets into my head…
Anton Bassov
Hi Daniel & Anton
My long ISRs were caused when a sound was played, so my ISR DMA operations were delayed.
I wanted to build a timeline which describes when every ISR/DPC on the system occured, but I could not see an entry in tracelog binary file that describes when it was ended (only when it started). So, I don’t understand how does tracerpt gives statistics about ISR/DPC duration…
Anton: What is SMI?
Thanks,
Tal
On 19/09/2011 08:29, xxxxx@yahoo.com wrote:
Hi Daniel& Anton
My long ISRs were caused when a sound was played, so my ISR DMA operations were delayed.
I wanted to build a timeline which describes when every ISR/DPC on the system occured, but I could not see an entry in tracelog binary file that describes when it was ended (only when it started). So, I don’t understand how does tracerpt gives statistics about ISR/DPC duration…
Anton: What is SMI?
There’s an overview of SMI and SMM at
http://en.wikipedia.org/wiki/System_Management_Mode .
–
Bruce Cran
> Anton: What is SMI?
SMI is System Management Interrupt…
Anton Bassov
On 18-Sep-2011 21:04, xxxxx@hotmail.com wrote:
> This exactly means “Windows is not a real time OS”.
Well, x86 platform in itself is not really suitable for real-time tasks (at least hard-RT ones) due to the possibility of SMI, which is totally transparent to the OS software. At the OS level, you don’t know what particular event/action triggers it; you cannot mask it; you cannot intercept it - it is a complete “terra incognita” to the OS software; it has the highest priority, and handling it can take hundreds of microseconds.
There are lots of x86 Windows compatible boards and SOMs for
“real time” applications these days. They can run SMI-free, at least
there is BIOS setting to disable SMI.
– pa
> at least there is BIOS setting to disable SMI.
Seems to be a good option for someone who wants to take the risk of burning the CPU…
Anton Bassov
> there is BIOS setting to disable SMI.
The thing is that on many machines the ACPI EC is implemented as SMI BIOS code.
–
Maxim S. Shatskih
Windows DDK MVP
xxxxx@storagecraft.com
http://www.storagecraft.com
On 19-Sep-2011 21:27, Maxim S. Shatskih wrote:
> there is BIOS setting to disable SMI.
The thing is that on many machines the ACPI EC is implemented as SMI BIOS code.
Yes, cheap substitution of embedded controller.
One can’t have all that at once. Or cheap, or realtime.
– pa