doveman

Hmm, it's crept up from 41s to 122s, (next boot 98s) now! I disabled most startup apps and now it's 81s but I still think that's too high. Obviously having apps loading is going to increase it from 41s without any loading but I shouldn't think it should triple! I installed Comodo Firewall again yesterday so did the "xbootmgr -trace boot -prepSystem -verboseReadyBoot" after that but the 122s was immediately following that. If you could check the boot trace for me I'd be grateful. https://docs.google.com/file/d/0B1fDI89phEESTVU3YzZQWTNrRXc/edit?usp=sharing

For me it just seems stuck on 0.01 or 1 whatever the graph is doing and even if it showed something useful, there's no logging or way to correleate the disk queue with what is happening at that moment on the system.

On one boot today I got this Background optimizations (prefetching) took longer to complete, resulting in a performance degradation in the system start up process: Name : BackgroundPrefetchTime Total Time : 39702ms Degradation Time : 36964ms Incident Time (UTC) : ‎2013‎-‎07‎-‎31T10:16:45.765200400Z but the boot time was not unusual (sometime it takes 49s, other times around 69s), which doesn't seem to make much sense if this task took 39s, which was an degradation of 36s. Should I just ignore this task in future? Windows has started up: Boot Duration : 59575ms IsDegradation : false Incident Time (UTC) : ‎2013‎-‎07‎-‎31T10:16:45.765200400Z Both these events were logged at 11:19:03, so I'm not sure what the Incident Time is referring to.

I found this article about measuring Disk Latency.https://blogs.technet.com/b/askcore/archive/2012/02/07/measuring-disk-latency-with-windows-performance-monitor-perfmon.aspx?Redirected=true I don't really understand it all but I did try looking at the Counters in Performance Monitor but it didn't really mean much to me. I guess what I really need is a way to monitor the latency / IO which also shows what activity is happening, which also logs it as it's almost impossible to catch things in real-time when everything is constantly changing.

Thanks. That TVService causes a shutdown delay as well, as although it closes quickly, within 2s, it doesn't seem to tell Windows that it's closed and so Windows waits 12s or so before continuing. They're looking at that, I'll have to ask if anything can be done about the startup as well but probably not as the tuner card has to initialise, etc. Strangely though, on my next boot it was back down to 43s! I don't actually have much loading at startup at all, just the bare minimum and have left most stuff to be started as needed by the user. I probably will re-enable some things that really should be started automatically but I want to make sure the baseline is stable first. Compared to the boot you analysed and my last boot it shows MainPathBootTime 38563 vs 18469 BootPostBootTime 46700 vs 23500 I'll have to keep an eye on it for a few days and see if it behaves.

Hmm, my boot time has crept up again, to 108s, then 112s and now down to 85s, whereas it was as low as 44s before. I've changed the SATA ODD cable and the IDE HDD cable as they turned out to be dodgy and put the PCI tuner card back in but otherwise I don't think I've changed anything. I'm not seeing any troublesome durations on the storage devices like there were before. The only degradation issues listed in the logs are This application took longer than usual to start up, resulting in a performance degradation in the system startup process: File Name : lpuninstall.exe Friendly Name : LastPass Installer Version : 2.0.20 Total Time : 7177ms Degradation Time : 2177ms Incident Time (UTC) : ‎2013‎-‎07‎-‎16T16:06:17.749600400Z This application took longer than usual to start up, resulting in a performance degradation in the system startup process: File Name : svchost.exe Friendly Name : Host Process for Windows Services Version : 6.1.7600.16385 (win7_rtm.090713-1255) Total Time : 6450ms Degradation Time : 1450ms Incident Time (UTC) : ‎2013‎-‎07‎-‎16T16:06:17.749600400Z which don't explain the increase. etl uploaded to https://docs.google.com/file/d/0B1fDI89phEESZHAyYkNqX0dBNTA/edit?usp=sharing

I had a conversation with the author of LatencyMon. He first told me "The interrupt-to-latency test is only meaningful without having any other programs running in the background." to which I replied "You say it's only meaningful without having any other programs running but my concern is that if I'm getting high latency spikes when certain activity happens, such as writing to disk, then these spikes are going to cause issues with audio/video when this activity happens whilst using A/V software, gaming, etc." and he replied "The interrupt-to-latency monitor simulates a critical audio process. This is why it is not recommended to be running any other activity on top. That said, if you would like to paste the contents of the report view in a message, we don’t mind to take a look to see if there is anything peculiar in your system." So I sent him three reports, one at idle, one launching Iron and one launching Mediaportal and he replied "Your system appears to be OK. Regarding excessive hard disk usage and spikes under load, I suggest you make sure that your harddisks have enough free space and are not fragmented. You can use the standard Windows defragmentation tool for that. If fragmentation on your system is low and not a problem then I suggest considering if excessive paging might be the problem (take a look at your memory load, kill of processes that consume a lot of memory, etc.)" My HDDs are defragged and have plenty of space, so that's not an issue. I also told him that I see tons of hard pagefaults from svchost.exe when analysing the disk with Windows defrag but no latency spikes and he replied "Whether they are connected depends on the priority of the process that incurs the page fault. Defrag runs at lower or idle priority. In principle, only a real-time priority process/thread can compete and thus influence the interrupt to process latency measurements." Which makes sense, although it doesn't get me any nearer to understanding why I'm getting latency spikes with MediaPortal, where it does matter as that's for playing media and having spikes during that could cause audio/video glitches. I guess I should ask on the MediaPortal forums if anyone knows anything about that.

OK, thanks. I've got a backup just in case anyway

Is it safe to use xbootmgr -trace shutdown -noPrepReboot -traceFlags BASE+CSWITCH+DRIVERS+POWER -resultPath C:\TEMP for shutdown tracing or do we need to leave DRIVERS out, as we do for boot tracing to avoid BSODs?

Thanks. Doing that reduced it from 61s to 40s I've disabled most of my boot apps and don't even have an AV or Firewall installed at the moment whilst I debug some issues, so it will increase once I re-add those but hopefully I can keep it down to something reasonable (originally it was something like 266s with all the apps loading!).

Thanks. I'm really at a loss to know what to do. The latency spikes would appear to be related to HDD writing and nothing to do with pagefaults. Running Windows defrag and analysing my partitions, svchost generates a ton of pagefaults (like 30000) but no latency spikes. If I Analyse in CCleaner, no latency spikes but when I run the Wipe, they appear. Iron seems to generate a spike (3500us) just as it's finished opening all the saved tabs, so perhaps it does some writing at that point. Then again, if I open a new tab and browse to a new page, that obviously writes to the temporary files and doesn't generate a spike. Opera Portable also generates a spike of around 1100us just as it finishes loading. Sometimes IE, which only opens with one tab, does and other times it doesn't generate a spike, whether I'm in Balanced or High Performance mode. I get the odd spike to 600-700us with various apps but that's below the threshold to trigger LatencyMon's warning, so they probably don't matter. Even in High Performance mode, opening MediaPortal generates several spikes from 1500us to 3908us. On the second launch, it hit 20874us and then 9000us. Even if I restart LatencyMon after MediaPortal has loaded, it spikes to around 2000us several times. It may be updating the media database in the background, which could involve writing new thumbnails, metadata, etc. Then again I can update/install software without triggering any spikes. Generally storport.sys is appearing from both ISR and DPC although sometimes ISR gets replaced by tcpip.sys or ndis.sys EDIT: Strangely, if I run DPC Latency Checker with Iron open, the highest spike is 168us over several minutes. If I close that and start LatencyMon however, I get a spike of 758us within 10s. I don't know if DPC-LC is just sampling at a lower frequency than LatencyMon and missing the spikes. With MediaPortal, the highest spike DPC-LC shows is 138us.

Nothing's connected to the Asmedia USB3 controller, just the Mouse dongle and Keyboard dongle connected to the top two USB2 ports on the rear of the board. Did you have a look at the DPC_S2d trace with the Nova-T card removed? I'd be interested to know if that shows less/no USB spikes.

Seems I removed the Nova-T card by mistake (thought I'd removed the Nebula card) but that makes it easier to test without it Here's another scan, doing the same tasks as before, without that card installed. I also disabled the HwInfo persistent driver in case that was causing problems: https://docs.google.com/file/d/0B1fDI89phEESM3NrMGFKSzdXX2c/edit?usp=sharing Monitoring the hard pagefaults I found: On first run, the process with the highest number of pagefaults is svchost at 190 (and rising) after about a minute. This isn't associated with high latency though, which is hovering below 75us with the odd spike to 200us and the highest around 400us. I noticed that HwInfoMonitor (a sidebar gadget) was showing about 10 pagefaults, so closed that and restarted LatencyMon and then it only showed a count of 3 pagefaults after 3 minutes, one on svchost.exe and one on explorer.exe. I'm not sure where the third one is hiding! Then I launched Iron, and got a latency spike of 12325us (and several below 1000us) and the pagefault count rises to 240 by the time all the tabs have loaded, but processes only shows 50 on Iron.exe, 3 on another instance of Iron.exe, 8 on TrustedInstaller.exe, 2 on svchost.exe, 1 on explorer.exe and 1 on another instance of iron.exe. The total count and the first instance of iron.exe are slowing rising, now on 264 and 66 respectively. Iron seems to open an instance of iron.exe for each tab, judging by Task Manager, so I'm not sure if this indicates that most of the pagefaults are associated with one particular tab. Then I closed Iron and re-enabled HwInfoMonitor and although it's still showing some pagefaults on that (6 after 1.5mins) I'm not seeing any of svchost.exe now. I did manage to open the trace with xperfview and opened "Detal Graph" from Disk I/O and Disk Utilisation (seems to open the same view) but I can't see where it shows the Disk Queue.

Thanks. I guess it could be that I'd put the HDD on the SATA3 port that reduced the queue, or it might be High Performance mode or it might just be that it's a different system/HDD I guess. Could you compare with DPC_Interrupt_S2 for me please, which was using SATA2 in Balanced Mode? The screen went blank when I ran HwInfo and when I next rebooted (after a hard reset) the Sidebar gadgets didn't appear and the mouse was stuck on busy and I couldn't do anything, so had to hard reset again, so I moved the HDD back to the SATA2 port. Mind you, both these problems happened before when it was on the SATA2 port and I thought I'd fixed them by uninstalling some software but anyway, at least it's booting again now. I'll try disabling the Hauppage Nova-T 500 TV Tuner card as that creates two VIA USB buses. I'm also using a wireless mouse and dongle and a separate wireless keyboard and receiver, so I don't know if those would cause latency problems.

I've now installed the ATI Chipset drivers and upgraded the Realtek audio drivers to 6923 on my other system and I am seeing storport.sys mentioned in LatencyMon, so it seems that comes as part of the AMD drivers. Latency was OK until I launched Iron and about 20s later it hit 3000us+, so again it was probably the HDD activity (51us ISR, 607us DPC currently). If I restart LatencyMon, the latency hovers between 80-200us with the odd spike to 569us, although it just hit 1222us. Launching Plex and it hit 4029us. I'll make a trace on this system, launching Iron and then Plex to see what it shows. EDIT: OK, with this trace I first launched IE, which opens with only one tab, as I saw previously in LatencyMon that caused a spike of 1700us. Then I launched Iron and left it to settle for one minute, then I launched Plex and refreshed a couple of the libraries, which didn't take long. https://docs.google.com/file/d/0B1fDI89phEEScVdxTVotODN3M00/edit?usp=sharing I thought I'd see if I could understand the trace myself but when I double-click on the etl, WPA opens but then says it's stopped working with the following details Problem signature: Problem Event Name: APPCRASH Application Name: wpa.exe Application Version: 6.2.9200.16384 Application Timestamp: 501077b4 Fault Module Name: clr.dll Fault Module Version: 4.0.30319.1008 Fault Module Timestamp: 517a18ff Exception Code: c0000005 Exception Offset: 000000000000d08d OS Version: 6.1.7601.2.1.0.256.1 Locale ID: 2057 Additional Information 1: 3749 Additional Information 2: 3749574877fa1c2583d7663bfe3c5c14 Additional Information 3: b4dc Additional Information 4: b4dcc7f0b08f3f363dd8378be51c7b0b Read our privacy statement online: http://go.microsoft.com/fwlink/?linkid=104288&clcid=0x0409 If the online privacy statement is not available, please read our privacy statement offline: C:\Windows\system32\en-US\erofflps.txt EDIT: Hmm, this seems interesting. As a test, I tried putting Windows Power Options in High Perfomance rather than balanced, which runs the CPU at full speed permanently and also disables "Link State Power Management". In this mode, I didn't see any spikes when launching IE, nor when running Plex. I still got a spike of around 2700us shortly after launching Iron though and another around 1600us when I was switching between tabs and scrolling through pages. I've uploaded the trace, repeating the same sequence of tasks as before, here https://docs.google.com/file/d/0B1fDI89phEESSU52VlVKQ0J3cW8/edit?usp=sharing EDIT2: I also updated the NIC, USB and SATA3 drivers and moved the HDD to the SATA3 port. Rebooting, it's still in High Performance mode and latency stayed under 250us at idle, no spike with IE, a spike to 2500us running Plex. With Iron however, I just got a spike of 4000us followed by one of 19536us! storport.sys is nowhere to be seen now the HDD is not connected to the AMD chipset SATA2 ports and instead ataport.sys is referenced again. Highest ISR of 32us for ataport.sys and DPC 130us for ntoskrnl but those figures are no higher than they were before the spikes happened so they don't seem very useful. I'll make another trace. Here it is https://docs.google.com/file/d/0B1fDI89phEESU0NIWHkyZXBYMzA/edit?usp=sharing

You might be right but I'm not seeing it come up on my other system which is also running in AHCI mode. On that, I haven't installed the AMD Chipset driver yet, so the controller is listed as "Standard AHCI 1.0 Serial ATA Controller" rather than "AMD SATA" (on the system the trace is from, there's also a "Standard AHCI 1.0 Serial ATA Controller" listed, with nothing attached, so I presume there must be another controller on the MSI board that's not part of the AMD 990 chipset.) In that case, the controller lists atapi.sys, ataport.sys, msahci.sys, pciidex.sys and the HDD lists disk.sys and partmgr.sys as on the other system.

Hmm, seems to be an epidemic. My post has disappeared too. Anyway, as I'm not sure which message you're replying to, can you confirm you're referring to DPC_Interrupt_3.zip? I'm still at a loss to understand why this storport.sys (which apparently is used for SCSI devices) is even being used on my system. In Device Manager, the AMD SATA Controller lists amd_sata.sys and amd_xata.sys, whilst the actual HDDs list disk.sys and partmgr.sys and I don't have any other storage devices connected.

I've had to restore my gaming PC from a True Image backup and am having problems with latency again. Previously I'd got it down to around 19us, with spikes around 100-200us. Now it's not going lower than around 82us, spending most of the time around 150-300ms but with very high spikes as shown in these screenshots. The first two were taken before installing the AMD Chipset drivers. These next two were taken after installing the AMD Chipset drivers. At first, it seemed better and stayed below about 300us but as soon as I opened my browser, with several tabs saved, it spiked to 500us and then LatencyMon stopped (I didn't notice at first). After I restarted it, I saw these very high spikes, which are lower than the spikes in the previous screenshots but still very high. etl uploaded to https://docs.google.com/file/d/0B1fDI89phEESclpuWXNvZGpSYVk/edit?usp=sharing

OK, I'll try that, if I can get the NIC working again that is as it's decided to go funny and says there's no network cable connected. I had the same problem before whenever I had my CF Card IDE adapter connected but I've tried disconnecting any IDE devices and it's still not working, so I might need to get yet another flippin motherboard

I've uninstalled Avast (and Sandboxie as I need to reinstall it) and I also disabled something in the BIOS called "SATA IDE Combined Mode" which seems to have fixed the BSOD I was getting when running Plex Media Server. It also installed two new devices/drivers for my IDE ports, so I think before they were somehow connected to the SATA controller and should now be separate. Anyway, even though my BootPostBootTime has come down from around 80s to 43s, my MainPathBootTime has now doubled from around 22s to 42s, giving a current boot time of around 85s. I see the ExplorerInit stage now takes about 24s whereas before it was only 3.8s! The drive enumeration time has come down a bit (4+X+0+0 seems to have disappeared). The SATA drive connected to the AHCI controller still shows as an IDE device here, so I guess that's just a quirk of the report. This is with my IDE DVD connected, I'll try adding my IDE HDD as well next. <phase name="bootStart" startTime="39" endTime="5926" duration="5887"> <pnpObject name="PCIIDE\IDEChannel\5+1270fc08+0+0" type="Device" activity="Enum" startTime="1393" endTime="4906" duration="3513" prePendTime="0" description="IDE Channel" friendlyName="ATA Channel 0"/> <pnpObject name="PCIIDE\IDEChannel\5+1270fc08+0+1" type="Device" activity="Enum" startTime="1394" endTime="4906" duration="3512" prePendTime="0" description="IDE Channel" friendlyName="ATA Channel 1"/> <pnpObject name="PCIIDE\IDEChannel\4+223a9b9c+0+1" type="Device" activity="Enum" startTime="253" endTime="1267" duration="1014" prePendTime="0" description="IDE Channel" friendlyName="ATA Channel 1"/> <pnpObject name="IDE\DiskSAMSUNG_HD103SJ_________________________1AJ10001\5+2ba897a2+0+0.0.0" type="Device" activity="Start" startTime="4933" endTime="5877" duration="944" prePendTime="944" description="Disk drive" friendlyName="SAMSUNG HD103SJ ATA Device"/> TVService and MPExtended still show a Total time of around 4.5s each but that's something I'll have to put up with unless the authors can reduce it somehow. I tried looking at the Disk Graph but didn't really understand it and couldn't see the Queue Depth, so I'm not sure if that's improved or not. ETL at https://docs.google.com/file/d/0B1fDI89phEESTHBRYjJ5UV9SQ2s/edit?usp=sharing 02_summary_end.xml

Thanks for that. The drives is weird as I only have a single SATA HDD attached to the AHCI controller, so I'm not sure why it's enumerating the empty IDE channels. I think there should only be two of those anyway as there's only a single IDE port, so Master and Slave. TVService and MySQL are used for MediaPortal (and MySQL also for my XBMC database) and are essential unfortunately and MPExtended Service is used to provide Browser/Internet access to the MediaPortal media files catalog/TV Guide so I need that as well but will ask if any of these can possibly be made faster to load. I'll try uninstalling Avast and redo the trace and then try with Avira AntiVir, which is the only other decent free antivirus I'm aware of (Avast is probably better in terms of fewer false positives but not worth it if it's going to cause other problems).

OK, I've done the procedure described here but I don't think it's helped, as my boot time before was 104s and after 107s (although that's close enough to say it's not changed). I've done a boot trace and uploaded it here if you could take a look for me https://docs.google.com/file/d/0B1fDI89phEESNFk0V2hyeGh3cXM/edit?usp=sharing I also made a summary_end.xml as described in that other post and have attached it in case it's easy to analyse than the .etl. From that, I can see that bootDoneViaExplorer="22711" and bootDoneViaPostBoot="108311" so the problem seems to be somewhere after Windows has booted to the desktop but the rest of the xml is rather confusing to me. 02_summary_end.xml

OK, I still prefer to use specific individual updates though. For instance, this one http://support.microsoft.com/kb/2617858 is to fix slow boots caused by WMI problems and I don't have any corresponding entries in my log, so probably don't need it. For others, it can be harder to decide as this one http://support.microsoft.com/kb/2510636 refers to svchost.exe locking on to a service but doesn't describe how to establish whether this is happening or not and therefore whether one needs the hotfix. Although my svchost.exe is dated 2009 and the hotfix one is newer, dated 2011, for all I know Microsoft have fixed the problem via Windows Update by changing some other files, making it unnecessary to update svchost.exe now. The hotfixes are also generally accompanied by this text "Apply this hotfix only to systems that are experiencing the problem described in this article. This hotfix might receive additional testing. Therefore, if you are not severely affected by this problem, we recommend that you wait for the next software update that contains this hotfix", which is why I wonder if they might not already have been applied to my system via Windows Update.

OK, thanks.

Thanks. Yeah I saw your warning but thought I'd try it anyway to see if it worked on my system One thing that was lost by using Last Known Good is that the path to xbootmgr isn't included in the Path variable but that's easy enough to fix and would be lost (along with more, most likely) by using System Restore anyway.