hIOmon SSD Performance Monitor - Understanding desktop usage patterns.

[vol7ron]

I've got to say, I stumbled across this post in searching for SSD Queue Depth and you guys are doing some great work!

I haven't read through all the posts, but the first page was enough to get some great information. Congrats to Ao1, Overthere, Computard, and the others that I have yet to come across.

[F@32]

Ao1, greatly appreciate your superb work on this. Would you mind updating the first post of this thread with conclusions you arrived to so far? There are bits and pieces spread all over, but nice short summary would be great. Like game loading is mostly at QD x, booting OS involves mostly small files read operation <4K, you won't see benefits with file copy unless you use Total Commander and etc. Thanks!

[Ao1]

Hi Fox32,

Thanks. I agree it might be helpful to condense and summarise everything in the first post.

I've also been thinking about looking at the impact of running different Cachman settings on a couple of raps in raid 0 during game play/ loading. For Black Ops I think I could get comparable performance metrics with an SSD.

I also wanted to monitor ramdisk game performance but I don't have enough RAM to install the game on it. I'm also not sure if hIOmon would work with a ram disk. I'd guess it would but I have not tried it.

I learnt something today on boot up. Nothing different to what I have observed via hIOmon but it explains what I could observe.

Boot up can be split into two processes. Main-path boot and post desktop boot.

Main-path boot is essential drivers and services to load the desktop. Once the desktop is loaded low priority drivers and processes start to load, including third party programmes configured to run at start up.

[Computurd]

Main-path boot is essential drivers and services to load the desktop. Once the desktop is loaded low priority drivers and processes start to load, including third party programmes configured to run at start up.

i knew that they loaded the OS in this manner, they started doing that with vista i believe in order to speed boot times. however, i did not know that they could be measured separately, that is awesome! i wonder what mine is setting at...you used hiomon to measure this correct?
this could be an excellent way for me to tweak my OS

[Ao1]

Hi Comp,

Main path boot time and post boot times can be found quite easily in the event viewer.

Here is a link that explains how to do it. (It's the same for Win 7).

http://www.zdnet.com/blog/bott/micro...up-secrets/246

Here the difference between a fresh install and a fully loaded system can be seen. (Both using the same system with SSD).

[F@32]

So, once we add SSD to the equation, we are mostly limited by its 4K QD1 random performance... Microsoft and app developers should start thinking about optimizing their code to unleash QD32 SSD performance. But of course, consideration for the lowest common denominator will always win.

[Anvil]

Fairly fresh install, just a few days old, a few apps installed, not clean iow.

Capture2.PNG

[Ao1]

Ao1, greatly appreciate your superb work on this. Would you mind updating the first post of this thread with conclusions you arrived to so far? There are bits and pieces spread all over, but nice short summary would be great. Like game loading is mostly at QD x, booting OS involves mostly small files read operation <4K, you won't see benefits with file copy unless you use Total Commander and etc. Thanks!

A summary is now complete on the first post. If anyone can see any errors or ommisions please let me know.

[Anvil]

I'll install hIOmon on my test rig today and make a few tests wrt your 512B findings in #241-#242, could be application specific.

Link to some usefull info on the magical 4KB

[Ao1]

Anvil I can see what you are saying. In order to maintain compatibility emulation is required to deal with legacy hardware and software that still see the world in 512 byte sectors.

According to this article the driver interface should convert 512 bytes to 4K reads/ writes on the physical device.

http://www.hitachigst.com/tech/techlib.nsf/techdocs/3D2E8D174ACEA749882577AE006F3F05/$file/AFtechbrief.pdf

I'm still seeing transfers less than 4k on the physical device however.

[Ao1]

Here I try an experiment. The image on the right captures metrics whilst playing Black Ops Multi Player. The Set Priority is set to High (via the Task Manager). The image on the left is when the Set Priority is left as Normal.
With The Set Priority set to High there is an improvement in the fast IOP count.

I haven't checked yet to see if it repeatable. Later I will try running multiple processes in high priority to see what happens. (Other than watch the CPU fry).

[Anvil]

Interesting, although I think you'll have to repeat a few times

Did you notice the 512B count?

[Ao1]

Large file transfers dominated. They were only a couple of entries under 4K

[overthere]

I have seen them before, but I thought that I'd take another quick look to help confirm Ao1's 512B sightings.

Earlier today I used the hIOmon "Physical Device Extended Metrics" support to help further determine, moreover, which specific files were incurring the "512 byte" data transfer lengths down at the physical device level within the OS I/O stack.

Both a Windows XP 32-bit and a Windows 7 64-bit system were used for this quick look. No specific applications were run on the XP system (just observed I/O operation activity for about 10 minutes or so). Same with the Win 7 system (that is, no particular applications run; simply observed I/O operation activity during the system services startup and the subsequent period in which the system was basically idle with no applications explicitly run).

For Windows XP, the following physical device (DR0) I/O operations were observed for these particular files:

1. C:\WINDOWS\SoftwareDistribution\DataStore\Logs\edb .log - 6 writes (all 512B); minimum read data transfer length was 32KiB
   
2. C:\WINDOWS\system32\config\software.LOG - 512B, 16896B, 4096B, 4096B, and 4096B to successive LBAs were written
   
3. C:\Documents and Settings\UserMe\ntuser.dat.LOG - this included 512B writes
   
4. C:\$Mft - 512B writes on some occasions; please note that this is a file-system metadata file

And for Windows 7, the following physical device (DR0) I/O operations were observed for these particular files:

1. C:\WINDOWS\system32\config\SOFTWARE - 512B written at various times
   
2. C:\Users\UserMe\NTUSER.DAT - similar to that noted above for XP; please note that I could simply open a DOS command prompt window so as to generate 512B writes to the physical device associated with this file
   
3. C:\WINDOWS\serviceProfiles\LocalService\AppData\Lo cal\lastalive0.dat - single 512B writes
   
4. C:\WINDOWS\serviceProfiles\LocalService\AppData\Lo cal\lastalive1.dat - same as immediately above
   (Please note that the file size for both of the "lastalivex.dat" files is 2048B; a single 512B write occurred alternately for each file every 60 seconds repeatedly)
   
5. 512B reads for various other files during the system services startup.

Overall, it should be noted that relatively few 512 byte data transfer lengths occurred (whether read or write) when considered within the context of the total of all the I/O operations performed to the physical device. But, as always, YMMV.

Also, the list of files mentioned above is not meant to be complete/exhaustive - rather it's simply the result of a quick look using hIOmon.

[johnw]

Thanks for the information on 512B IO. I'm not surprised that XP has 512B IO, but I am surprised and disappointed that Windows 7 does.

[Ao1]

Hi overthere,

I’m collecting data over a couple of days to get a wider picture and check my earlier finding, but so far all 512B IO activity has come directly from Win 7 (64).
Does hIOmon monitor the driver interface for physical device statistics? With 25nm I guess 8k emulation has to occur on the drive itself or maybe the device driver is 8K sector aware?

[overthere]

Hi overthere,
Does hIOmon monitor the driver interface for physical device statistics? With 25nm I guess 8k emulation has to occur on the drive itself or maybe the device driver is 8K sector aware?

Hi Ao1,

Not exactly sure what you mean by "physical device statistics". As you know, hIOmon is focused upon measuring and monitoring I/O operation activity and performance up at the application/OS/host level. It does not currently retrieve statistics/metrics that might be provided/exposed down at the "other end of the cable" (i.e., at the actual physical device).

Regarding 8k emulation, I suspect that you are alluding to the NAND 8KiB page size factor - which seems to me to be largely a "Flash Translation Layer (FTL)" issue and concern that generally is handled down at the actual device (although in some products it can be handled further upstream by device driver software).

In any case, any such "emulation" actions would not be directly visible at the points within the OS I/O stack that are monitored by hIOmon.

[Ao1]

Here is a brief snapshot of ongoing monitoring of physical device reads and writes. The data below is all reads.

I have only summarised reads less than 10,000B. So far 4K reads are dominating, but I've yet to build up a bigger picture.

The objective of the snapshot was to look at the read times below 10,000B. I averaged the read time transfers by the amount of times they occurred to try and give a balanced overview. I've arranged the results by the lowest read time. I was expecting anything over 4K to take longer and anything below to take just as long. Not so, and 512B actually took the longest time!

Specific 512B "offenders" are listed.

[johnw]

That is some really bizarre data. Could hIOmon have a bug? I just cannot make any sense of 4KB reads taking 0.25ms and 512B reads taking 14ms. I agree with you, that for reads, anything less than 4KB should take about the same time as 4KB, since the SSD must read the entire 4KB page anyway. But it should certainly not take a lot longer to do 512B reads. And the times for other reads less than 4KB seem random. It just looks like bad data.

If you were looking at writes, then I could understand 512B writes taking longer than 4KB writes, due to the way the SSD might have to split things up. But even then, I cannot see 512B writes taking more than 50 times as long as 4KB writes.

[overthere]

That is some really bizarre data. Could hIOmon have a bug? I just cannot make any sense of 4KB reads taking 0.25ms and 512B reads taking 14ms. ... I agree with you, that for reads, anything less than 4KB should take about the same time as 4KB, since the SSD must read the entire 4KB page anyway. But it should certainly not take a lot longer to do 512B reads. And the times for other reads less than 4KB seem random. It just looks like bad data.

If you were looking at writes, then I could understand 512B writes taking longer than 4KB writes, due to the way the SSD might have to split things up. But even then, I cannot see 512B writes taking more than 50 times as long as 4KB writes.

I would need to see the actual metrics data that was collected before I jump to any explanation, but one thing that I would suggest at the outset is that there is some contextual information missing here.

For example, how was the "PhyDev Read Time Average" value calculated? (Please note that the hIOmon software does not directly capture such an "average" metric). What was the queue depth at the time that the 512B I/O operation occurred? Did this write I/O operation occur in the midst of a "Flush Buffer" I/O operation? What other types of I/O operations occurred at the time that this particular 512B I/O operation was observed? Which specific file incurred this 512B write I/O operation. And so on.

In general, I try to understand the observed values of I/O operations within the context within which they occurred.

[Ao1]

Hi Ao1,

Not exactly sure what you mean by "physical device statistics". As you know, hIOmon is focused upon measuring and monitoring I/O operation activity and performance up at the application/OS/host level. It does not currently retrieve statistics/metrics that might be provided/exposed down at the "other end of the cable" (i.e., at the actual physical device).

Regarding 8k emulation, I suspect that you are alluding to the NAND 8KiB page size factor - which seems to me to be largely a "Flash Translation Layer (FTL)" issue and concern that generally is handled down at the actual device (although in some products it can be handled further upstream by device driver software).

In any case, any such "emulation" actions would not be directly visible at the points within the OS I/O stack that are monitored by hIOmon.

The image in post #260 was confusing me. From my understanding a data transfer is initiated by the file system driver, which then goes to:

1. Disk driver
2. Drive interface (512-byte emulation)
3. Storage media

I'm guessing that the drive interface is on the HDD itself.

What I think I see is that although Win7 is 4K aware that doesn't preclude it (or any other legacy application) from still sending out reads/ writes that are less than 4K.

When this happens the HDD has to then use the drive interface to convert the reads/ writes to 4K before they are physically read/ written on the media.

With regards to what hIOmon is monitoring I understand this to be the data transfer point initiated from the file system driver to the storage device (via the disk driver) as in image 2 on post # 203.

I would need to see the actual metrics data that was collected before I jump to any explanation, but one thing that I would suggest at the outset is that there is some contextual information missing here.

I've sent you an email with the PerfAnalysisExportFile. I haven't had a chance to look at writes yet.

Hopefully I did not mess up.

[overthere]

Ao1 kindly provided me with the "hIOmon Manager Export File" that contains the summary I/O operation performance metrics which were collected by the hIOmon software and which were the basis for his post #268 above.

Based upon my initial analysis of this export file, the metrics contained within the file appear valid.

The analysis is rather involved, but I will try to highlight at least some of the major points here. But first some important background information.

Firstly, the export file contains a default set of 66 summary metrics, which represent a modest subset of the over 200 or so summary metrics collected by hIOmon that are available for export. As a result, there are several additional metrics that if present within the export file might provide additional substantiation.

Also please note that no "I/O Operation Trace" metrics were collected; hence, there is other supplemental information that could also provide additional substantiation.

Secondly I would note that a "top-down", iterative approach is one which I generally recommend when using the hIOmon software to explore particular issues of interest (especially in contrast to starting out by collecting mountains of I/O trace data and then having to plow through it all so as to find, for instance, some anomaly - and assuming that you know what you are looking for from the start).

So the basic idea is to begin with a small but prudent set of summary metrics, and then subsequently include additional summary metrics as indicated/suggested by the analysis, and only resort to I/O operation trace data if actually needed - all dependent, of course, upon the particular topic that you are trying to tackle.

Anyway, here are some major items of note revealed by the export file:

1. The "aberrant 512B" was a single physical volume read I/O operation that took 499.2341 milliseconds to complete!
   
   
2. The "C:\Windows\SysWOW64\HsSrv.dll" file encountered this villainous data transfer during the 10 minute period prior to 18:14 on 28 February.
   
   
3. During that 10 minute time period, there were two file I/O operations to the "HsSrv.dll" file, both of which occurred concurrently (since the "Read Max Queue Len" metric value was "2").
   
   
4. Each of these file I/O operations transferred 26 bytes of data (since the "Read Xfer Max Size" value is "26" and the "Read Data Xfer" value - which reflects the total amount of data transferred - is "52").
   
   
5. The value of the "Read Random Access IOP Count" metric is "1", which indicates that the data transferred by these two file I/O operations was not contiguous.
   
   
6. The value of the "Read Time Total" metric is "998.5618 milliseconds"; this value reflects the combined total time required to perform both of these FILE level I/O operations. Please note that this is I/O operation response time observed at the file-level within the OS I/O stack and not that seen further down at the "physical volume" level within the OS I/O stack.
   
   
7. The value of the "Read IOP Max Time" is "499.3092 millseconds"; this value reflects the maximum I/O operation completion time observed for the associated file I/O operations. Consequently, one of the file I/O operations completed in 499.3092 millseconds (i.e., the max) and the other in 499.2526 millseconds (which combined equals the 998.5618 milliseconds read total time).
   
   This also coincides with both I/O operations having been queued together (see 3 above).
   
   
8. As noted in (1) above, the physical volume read I/O operation (to transfer the 512B) required to satisfy these two file I/O operations took 499.2341 milliseconds, which coincides with the I/O operation completion times for the associated file I/O operations.
   
   
9. Now for the bigger picture, the hIOmon software began monitoring I/O operations at approximately 18:03 on 28 February. Actually, the export file shows that the hIOmon software had previously been monitoring I/O operations the preceding day, with its last prior entry into the export file occurring at about 22:40 on 27 February.
   
   Generally the hIOmon software is by default started automatically when the various services are started as part of the system boot process. There is typically quite a bit of I/O operation activity occurring as the various services get up and running.
   
   Indeed, the "device summary" metrics within the export file shows during the approximately 10 minute period (ending about 18:13) shows that there were 31,337 physical volume read I/O operations that transferred a total of 691,739,648 bytes of data, with a maximum data transfer size of 29,618,176 bytes, a "Read Max Queue Len" of "41", a total combined time of 24.9406942 seconds, and a "Read IOP Max Time" of 500.0811 milliseconds (so some other physical volume read I/O operation was even more unfortunate than the aberrant 512B ).
   
   On the write side during this same 10 minute period, there were 7,273 physical volume write I/O operations that transferred a total of 226,802,176 bytes of data, with a maximum data transfer size of 2,105,344 bytes, a "Write Max Queue Len" of "34", a total combined time of 3.3205158 seconds, and a "Write IOP Max Time" of 19.8715 milliseconds.

Overall then, it appears that the "aberrant 512B" got caught up in the physical volume I/O operation activity that ensued as part of the services startup activities performed when the system was started.

As mentioned above, further substantiation would require that additional summary metrics be included within the export file.

[johnw]

Overall then, it appears that the "aberrant 512B" got caught up in the physical volume I/O operation activity that ensued as part of the services startup activities performed when the system was started.

So, would it be reasonable to conclude that this storage device sometimes has very slow 512B IO when other IO is going on in parallel?

[overthere]

So, would it be reasonable to conclude that this storage device sometimes has very slow 512B IO when other IO is going on in parallel?

I don't think so at this point. Some things to consider that immediately come to mind:

1. This export file is a sample of one. I think that it would be helpful to monitor over a longer period of time, look at systems other than Ao1's, etc. to see the extent of repeatability, etc.
   
   
2. There were a dozen or so other 512B physical volume read I/O operations, with only 6 other ones above 1 ms response time (the highest being 1.626 ms) and all of the rest were under 1ms.
   
   So the one "aberrant 512B" was the notable exception.
   
   
3. The additional metrics that hIOmon can collect/export could provide a crisper picture as to exactly what was going on ostensibly "in parallel".
   
   For example, specifically what other kinds of I/O operations were in progress at the time that the "aberrant 512B" came into the mix? And what were they doing (e.g., data transfer sizes) and what did their response times look like?
   
   Did the aberrant 512B get caught amidst a bevy of write I/O operations? Or a "flush buffer" I/O operation? And so on.

Overall, I would be hesitant to generalize at this point.

[Ao1]

I checked out AS SSD with hIOmon on a SSD with no OS. By running each benchmark separately I can isolate performance.

Access times are calculated on a write data transfer size of 512B with a total of 1,087,369,216 bytes transferred.

Access times are calculated on a read data transfer size of 32,768, with a total of 196,608 bytes transferred.

Edit: Whoops messed up. 4K write transfer. Read = 491,520 bytes transferred.