Mike Chaney's Tech Corner

Mike's Software => Qimage Ultimate => Topic started by: steveren on April 30, 2014, 01:37:47 AM



Title: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on April 30, 2014, 01:37:47 AM
I've was running 2014.137 until recently when I upgraded to .210 (and subsequently .213). Everything is much slower with these newer versions.

The reason seems to be excessive disk I/O. I note that simply placing a roughly 2MB image on a page causes hundreds of MB of disk reads! I've seen the same thing on two different Windows installations (Win7 32 and 64-bit) and also in Linux under Wine. Even deleting an image from the page, which shouldn't involve reading any data, causes vast amounts of activity.

I'm reverting to .137 for now!


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on April 30, 2014, 02:03:09 AM
It's not putting the image on the page that is causing disk I/O.  You've got something else going on.  Either it is building thumbnails or raw cache at the same time or something else is causing the disk I/O.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on April 30, 2014, 02:29:03 AM
Sorry, that's not the case. I've watched what happens with both Windows and Linux monitoring tools and it's perfectly clear that the disk I/O is in direct response to my actions. The exact same actions in .137 are fine. It is consistent and repeatable across three very different environments: real PC running Win7/32; VM running Win7/64; PC running Linux+Wine. If the images are on a remote drive, I see huge network transfers, not local disk.

Whatever is happening, it's absolutely real.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on April 30, 2014, 02:39:00 PM
210 and 211 have the exact same amount of disk reads as 137: as checked using Windows Process Explorer.  Now starting with 212 (and 213) there will be more disk reads because of the extended EXIF info.  I can probably optimize that to use less disk I/O but you shouldn't have to go back prior to 211 to get the same speed and disk I/O as 137.

I assume you are only worried about this WRT network disk I/O as you'd never notice the difference on a local hard drive.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on April 30, 2014, 04:20:53 PM
Perhaps I'm not making myself clear.

This isn't a minor difference due to reading EXIF data for new functionality, this is a massive difference which can only be due to a program bug. Obviously not one that shows up in all cases, but with the job I'm trying to do, it's absolutely consistent.

This is sluggish to the point of near-unusability even from a local disk, and with a GbE network connection to an SSD or a virtual network connection that's actually local physically, performance isn't much different (good or bad).

I'm talking several seconds for almost any operation, no matter how simple, such as just removing an image from the queue!

So if I:

  • Run the .137 installer; start QIU; load my job; start working on it; everything is great.
  • Run the .21x installer, overwriting the .137 installation; it's treacle.
  • Re-run the .137 installer; back to normal.




Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on April 30, 2014, 05:53:12 PM
Please give 2014.214 a try.  I've optimized the disk I/O and it offers even less disk I/O than the older 137.  If you still have a problem with 2014.214 then we'll need to look elsewhere like memory problems causing a swap file, anti-virus interference, or the like.  In the case you still see the problem, please provide the type of machine, OS you are running, and amount of available memory: you can see that by clicking "Help" in Qimage Ultimate and then holding the shift key while you click "Analyze Current Settings".

Regards,
Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on April 30, 2014, 11:16:09 PM
Will do, but seriously, this is not swapfile thrashing or anything like that. I'm a software developer myself and I know a program doing something grossly wrong when I see it  :-)

When I see hundreds of megabytes - this is not an exaggeration - being read simply to open a 2MB image with no other stress factors on the machine, that is not correct behaviour!


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 01, 2014, 12:26:17 AM
Ah, 214 is better, but still not good. It's a kind of treacle vs molasses comparison :-(

However, I noticed it was pretty snappy before I loaded my job, so it looks as though it might be spuriously re-reading every file in the job queue on every operation!

Anyway, here's a link to a screen capture video showing exactly what I'm talking about. I do the exact same things in 137, 213 and 214 and you can see that 137 is instant, 213 is a slug on valium, and 214 is the slug on valium after it's had a cup of coffee :-)

http://stvren.webspace.virginmedia.com/QImage%20problem%20demo.avi (http://stvren.webspace.virginmedia.com/QImage%20problem%20demo.avi)


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 01, 2014, 01:15:16 AM
And here are some Sysinternals Process Monitor logs of the drag-to-page operation. It's interesting that the 213 log is about 54MB and the 214 log just over 60, despite 213 being noticeably slower. OTOH, the 137 log is 4 - four! - MB. That's an awful lot of I/O that wasn't happening before.

Some of the issues are obvious, such as file I/O on every mouse move event when the pointer is over a thumbnail, but that'll mostly be cached by the OS and fast enough not to be a problem on a modern system. Other stuff I don't understand at all, such as the many attempts to access the offline files cache (c:\windows\csc) when I've got offline files disabled.

http://stvren.webspace.virginmedia.com/ProcmonLogs.zip (http://stvren.webspace.virginmedia.com/ProcmonLogs.zip)


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 01, 2014, 02:49:47 AM
Will do, but seriously, this is not swapfile thrashing or anything like that. I'm a software developer myself and I know a program doing something grossly wrong when I see it  :-)

When I see hundreds of megabytes - this is not an exaggeration - being read simply to open a 2MB image with no other stress factors on the machine, that is not correct behaviour!

It's only "incorrect behavior" if it causes an issue with operation and the issue on yours seems quite exaggerated.  Trolling every byte that goes in an out of the hard drive may be helpful information but it is not the cause of the speed problem.  It may be a clue, but it isn't the problem.  Even a slow system can read 25 MB of data in a fraction of a second.  Even with your job of over 100 prints, 214 is only reading a couple dozen megabytes (not several hundred) when you add a new image, mostly reading only thumbnails to determine changes... and all of those should be cached in the disk cache.  So I ask again, what OS are you running and on what type of machine.  I'll try to further optimize things but on my system, it isn't taking nearly as long to do those operations so at this point, I just want to figure out whether I'm putting wings on a dinosaur (a Pentium 4 running XP) or if yours is a reasonably modern system: that would help me determine the severity of the problem and where to look in the code.  It looks like Win7 at least with 4 CPU's but I notice you are using the Y drive.  I have no idea what type of drive that is: if it's a USB 2.0 drive or something slow, I may have to take that into account too in what I'm doing.

BTW every version since the beginning has disk I/O as you run your mouse over the thumbnails: it is reading the header of those images to display EXIF information in the hotbar at the bottom.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 01, 2014, 12:31:43 PM
BTW no argument that 200 is slower when you get into larger print jobs (over about 100), I just don't attribute it to disk I/O.  I just did a job of about 250 prints and did some diagnostics on where the code is spending most of its time by putting in timers.  Turns out that disk I/O contributed very little but the most time was being spent decoding of the JPEG thumbnails.  When I replaced the JPEG thumbnails with uncompressed BMP images (still from the disk), things were nearly instantaneous even though it was using even more disk reads for the larger size BMP files.  Obviously that's not going to be my solution but I'll look later to see what I can do about using another method to check page formatting rather than using the thumbnails to discover size and cropping.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 01, 2014, 08:43:27 PM
v2014.115 corrects the slow-down with larger jobs (many prints).

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 01, 2014, 09:21:18 PM
Ok, I've analysed the procmon logs and I now know more about what's going on, if not why.

This is for a simple drag'n'drop from the folder thumbnail listing to a new blank page at the end of an existing multi-page job. All files are on the local drive and I'm only looking at file read events.

137: the file being placed on the page is read. The process is horribly inefficient, though, as it involves over 2,200 separate read operations, almost all of which are for only a single byte, and many bytes are re-read twenty-five times! Yes, of course, most of those will come from OS cache, but it's still a hell of an overhead calling into the kernel like that rather than maintaining a single in-memory copy.

214: starts much as 137 although the exact pattern of reads is slightly different and actually comes to about 2,400 operations. However, it then goes on to issue 179 reads for every file in the job queue again mostly reading one byte at a time. With 64 images in the queue, this adds up to over 11,500 ops! Remember that I'm appending to the end of the queue on a blank page: nothing whatsoever has changed that needs re-reading.

But it gets worse. I edit the page and change the picture location, just typing a number into one of the position boxes.

137: It just moves the picture.

214: Over 23,000 read ops! Again the whole queue mostly one byte at a time.

Sorry, Mike, but that's a bug in my book. I haven't even looked at other I/O ops than just reading my data files, but there's clearly something wrong.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 01, 2014, 09:28:56 PM
Forgot to add that I compared 213 as well, although that's water under the bridge now. It was basically similar to 214 except that it was also reading the entire image data for the queue, not just what is I presume the EXIF metadata. That explains the 'hundreds of MB' observation and why 213 was even slower than 214.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 01, 2014, 09:32:19 PM
First, you are making many assumptions about what needs to be done and what you think should be done.  Your heuristics are also wrong.  There is nothing that is reading one byte at a time and certainly not the same byte over and over: your report may show that but it is inaccurate.  There are also times that QU saves undo information after certain operations.

Second, none of that matters in 215 as it is efficient and there are no unreasonable delays.  Even with hundreds of images in the queue, performing an operation only results in a few MB being read from the HD.  There are times when you add an image or move an image that can affect pages other than the one you are working on and I'm certainly not going to rewrite the program to build special cases that optimize things like freehand or single page editing when it'll only save maybe 4 MB of disk reads (reads that have already been cached into RAM) and a quarter second.  So 215 is both efficient and manageable from a code standpoint.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 01, 2014, 10:30:12 PM
Mike, these logs are from Sysinternals' (now part of Microsoft) procmon tool. THEY SHOW ACTUAL OPERATING SYSTEM CALLS.

There are no 'heuristics' and it doesn't matter what you think your code is doing, I'm telling you what Windows says your code is doing. Maybe you are using some third-party library, but something somewhere is doing it.

Quote
First, you are making many assumptions about what needs to be done and what you think should be done

If you can explain to me why moving an image on the page needs the entire queue to be re-read, then I will apologise for making assumptions.

I'll try out 215 and see what happens, but don't blame the messenger.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 01, 2014, 10:54:13 PM
Ah, 215 is definitely a big step in the right direction :-)

It's still re-scanning the queue unnecessarily, but at least it's doing so in a much more sensible manner.

Let me show you what kind of things were happening with 214:

Code:
Time of Day	        Operation	Path                                                            Detail
18:45:20.5794889 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
18:45:20.5795171 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
18:45:20.5795304 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 2, Length: 1, Priority: Normal
18:45:20.5795402 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 3, Length: 1, Priority: Normal
18:45:20.5795496 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 4, Length: 2, Priority: Normal
18:45:20.5795632 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 6, Length: 10,385, Priority: Normal
18:45:20.5795995 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 10,391, Length: 1, Priority: Normal
18:45:20.5796103 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 10,392, Length: 1, Priority: Normal
18:45:20.5796198 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 10,393, Length: 2, Priority: Normal
18:45:20.5796299 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 20,697, Length: 1, Priority: Normal
18:45:20.5796411 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 20,698, Length: 1, Priority: Normal
18:45:20.5796505 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 20,699, Length: 2, Priority: Normal
18:45:20.5796606 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,275, Length: 1, Priority: Normal
18:45:20.5796700 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,276, Length: 1, Priority: Normal
18:45:20.5796802 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,277, Length: 2, Priority: Normal
18:45:20.5796913 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,279, Length: 693, Priority: Normal
18:45:20.5797043 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,972, Length: 1, Priority: Normal
18:45:20.5797140 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,973, Length: 1, Priority: Normal
18:45:20.5797231 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,974, Length: 2, Priority: Normal
18:45:20.5797332 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,988, Length: 1, Priority: Normal
18:45:20.5797465 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,989, Length: 1, Priority: Normal
18:45:20.5797563 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21,990, Length: 2, Priority: Normal
18:45:20.5797664 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,122, Length: 1, Priority: Normal
18:45:20.5797783 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,123, Length: 1, Priority: Normal
18:45:20.5797877 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,124, Length: 2, Priority: Normal
18:45:20.5797978 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,141, Length: 1, Priority: Normal
18:45:20.5798072 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,142, Length: 1, Priority: Normal
18:45:20.5798167 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,143, Length: 2, Priority: Normal
18:45:20.5798268 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,147, Length: 1, Priority: Normal
18:45:20.5798362 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,148, Length: 1, Priority: Normal
18:45:20.5798456 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,149, Length: 2, Priority: Normal
18:45:20.5798558 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,567, Length: 1, Priority: Normal
18:45:20.5798652 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,568, Length: 1, Priority: Normal
18:45:20.5798743 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,569, Length: 2, Priority: Normal
18:45:20.5798844 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22,581, Length: 1, Priority: Normal
18:45:20.5801933 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
18:45:20.5802164 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 12, Length: 1, Priority: Normal
18:45:20.5802310 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 13, Length: 1, Priority: Normal
18:45:20.5802464 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 16, Length: 1, Priority: Normal
18:45:20.5802642 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 17, Length: 1, Priority: Normal
18:45:20.5802792 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 18, Length: 1, Priority: Normal
18:45:20.5802939 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 19, Length: 1, Priority: Normal
18:45:20.5803085 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 20, Length: 1, Priority: Normal
18:45:20.5803225 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 21, Length: 1, Priority: Normal
18:45:20.5803368 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 22, Length: 1, Priority: Normal
18:45:20.5803508 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 23, Length: 1, Priority: Normal
18:45:20.5803651 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 24, Length: 1, Priority: Normal
18:45:20.5803801 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 25, Length: 1, Priority: Normal
18:45:20.5803944 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 26, Length: 1, Priority: Normal
18:45:20.5804087 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 27, Length: 1, Priority: Normal
18:45:20.5804234 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 28, Length: 1, Priority: Normal
18:45:20.5804391 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 29, Length: 1, Priority: Normal
18:45:20.5804534 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 30, Length: 1, Priority: Normal
18:45:20.5804670 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 31, Length: 1, Priority: Normal
18:45:20.5804810 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 32, Length: 1, Priority: Normal
18:45:20.5804949 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 33, Length: 1, Priority: Normal
18:45:20.5805089 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 30, Length: 1, Priority: Normal
18:45:20.5805229 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 31, Length: 1, Priority: Normal
18:45:20.5805375 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 62, Length: 1, Priority: Normal
18:45:20.5805511 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 63, Length: 1, Priority: Normal
18:45:20.5805651 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 64, Length: 1, Priority: Normal
18:45:20.5805791 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 65, Length: 1, Priority: Normal
18:45:20.5805934 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 66, Length: 1, Priority: Normal
18:45:20.5806073 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 67, Length: 1, Priority: Normal
18:45:20.5806213 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 68, Length: 1, Priority: Normal
18:45:20.5806353 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 69, Length: 1, Priority: Normal
18:45:20.5806503 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 34, Length: 1, Priority: Normal
18:45:20.5806642 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 35, Length: 1, Priority: Normal
18:45:20.5806785 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 36, Length: 1, Priority: Normal
18:45:20.5806925 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 37, Length: 1, Priority: Normal
18:45:20.5807065 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 38, Length: 1, Priority: Normal
18:45:20.5807204 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 39, Length: 1, Priority: Normal
18:45:20.5807354 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 40, Length: 1, Priority: Normal
18:45:20.5807494 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 41, Length: 1, Priority: Normal
18:45:20.5807637 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 42, Length: 1, Priority: Normal
18:45:20.5807777 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 43, Length: 1, Priority: Normal
18:45:20.5807916 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 44, Length: 1, Priority: Normal
18:45:20.5808053 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 45, Length: 1, Priority: Normal
18:45:20.5808196 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 42, Length: 1, Priority: Normal
18:45:20.5808335 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 43, Length: 1, Priority: Normal

and that's just a tiny fragment!

Now, with 215 we have,

Code:
Time of Day	        Operation	Path                                                            Detail
23:38:07.9378463 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9378735 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9385815 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:07.9436177 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9450461 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9450636 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9455425 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:07.9458382 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:07.9512225 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:07.9546062 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1516328 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1516751 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1527174 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.1576423 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1587981 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1588152 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1597358 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:09.1601899 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.1661156 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.1702149 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.4348676 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:09.4351559 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.4413609 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.4439406 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.2167168 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:10.2170013 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.2221143 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.2245474 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.3924214 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104414-0002.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.3941661 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104414-0002.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.3974841 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104320-0001.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.3995682 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104320-0001.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4028778 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113048-0003.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4048243 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113048-0003.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4087316 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113458-0004.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4116936 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113458-0004.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4151216 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4188303 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4222834 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144427-0006.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4258465 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144427-0006.jpg Offset: 0, Length: 2, Priority: Normal

Still some redundancy in the reading but far less! It's still noticeably less snappy than 137 but definitely back in the realm of usability :-)


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 02, 2014, 12:12:34 AM
Ah, 215 is definitely a big step in the right direction :-)

It's still re-scanning the queue unnecessarily, but at least it's doing so in a much more sensible manner.

Easy.  I'll give you two simple examples.  If you're in one of the automatic placement modes, changing the size of the last image (or images) in the queue can move it to a prior page: didn't fit before on the prior page, now it does.  It gets worse if you are working on an image in the middle of the job.  Another example, you've had QU open for a while and you're using other programs (like a photo editor).  You edit one of the images on page 1, maybe even changing the size of that image, and then you save it.  In QU's pagination routine, it has to check all images on all pages to determine if they are the same resolution, orientation, that the specifics of that image (in the EXIF) like color space haven't changed, and that the time/date hasn't changed.  If this isn't done after each operation that results in any change to your job, you'll be unaware that the job you see on screen isn't the one that is actually going to print.  Some changes could even push images you are currently looking at/working with on one page to push off to other pages or images from prior pages to end up on the page you are working with.  And... it only does the minimum it needs to in order to determine that: it isn't reading the images; just headers, modified date/time, and such.  It's possible that the pagination process could be "short cut" if the entire document is in freehand mode and you're working on the last page but I don't see putting that code in (and the potential bugs it could cause) being worth it to gain .25 seconds of refresh time on a job with 200 prints.

Quote
Now, with 215 we have,

Code:
Time of Day	        Operation	Path                                                            Detail
23:38:07.9378463 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9378735 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9385815 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:07.9436177 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9450461 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9450636 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:07.9455425 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:07.9458382 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:07.9512225 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:07.9546062 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1516328 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1516751 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1527174 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.1576423 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1587981 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1588152 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.1597358 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:09.1601899 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.1661156 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.1702149 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:09.4348676 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:09.4351559 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.4413609 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:09.4439406 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.2167168 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 50, Priority: Normal
23:38:10.2170013 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.2221143 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.2245474 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.3924214 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104414-0002.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.3941661 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104414-0002.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.3974841 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104320-0001.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.3995682 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-104320-0001.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4028778 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113048-0003.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4048243 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113048-0003.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4087316 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113458-0004.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4116936 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-113458-0004.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4151216 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4188303 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144212-0005.jpg Offset: 0, Length: 2, Priority: Normal
23:38:10.4222834 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144427-0006.jpg Offset: 0, Length: 1,024, Priority: Normal
23:38:10.4258465 ReadFile C:\Users\steve\Pictures\Malta 2014\20140221-144427-0006.jpg Offset: 0, Length: 2, Priority: Normal

Still some redundancy in the reading but far less! It's still noticeably less snappy than 137 but definitely back in the realm of usability :-)


As far as reading a few bytes at a time, that's pretty typical of software that reads EXIF information.  You seek to a location in the file, read a few bytes that tells you the next IFD in the header, that gives you a new offset, you seek to that offset, pick up the next entry, and continue.  Each entry in the IFD tell you where you need to seek in the file and how many bytes need to be read for that entry.  Without parsing the header in this fashion, the only option is to read the ENTIRE file into a buffer, so this is very efficient.  And as I'm sure you know, the OS doesn't actually read one byte at a time from the file.  It is buffered by sector.  So while QU is parsing in that fashion, there is absolutely nothing wrong with it!

The only thing I see in your log (I use the same ProcMon BTW) is that while I can expect two or possibly three reads from the first few bytes of the file as there may be several procedures (and even multiple threads) accessing the same file or reading the header/formatting bytes, there is no way I can recreate as many reads from offset 0 as you are showing.  I can get two and sometimes three reads of the first 2 or 4 bytes in the file which is to be expected (and again, no problem at all since after the first read, you're just accessing RAM anyway).  For me to find an explanation for the extras you're seeing, I'd need to know exactly what operation you performed in order to see those.  Moving the mouse over a JPEG, adding the JPEG to the queue, etc. only causes 2-3 reads of the same bytes for me for a given file: only once at the beginning of the file and never repeating after that.

But again, I think it's really become counterproductive at this point.  I'm not finding 215 any slower than 137 and in some cases quite a bit faster.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 02, 2014, 12:52:42 AM
Sorry... looks like I hit the edit button again instead of quote...


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 02, 2014, 04:12:56 PM
Sorry: wasn't able to retrieve your post that I edited by mistake because I closed FireFox before I could recover it so I just removed it with a note because I didn't want it to look like you posted something that had my replies.  In any case, I was able to find one more area to improve where more information than necessary was being read from some image formats (hence why I wasn't seeing it all the time).  I had been working mostly with raw and TIFF but I noticed the potential for improvement when I went crazy and added every image in my "testimages" folder (about 1100 images) and started tracing.  Found some JPEG's and a couple others that were being read more than once which could obviously be more efficient.

The final speed improvement will be a part of 216 and it will be faster than any prior version when doing any type of operation on the job!

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: Terry-M on May 03, 2014, 08:42:34 AM
I have been following this thread with curiosity but I don't often have more than 100 images in the queue so I have done some tests of my own. Rather than use terms like "treacle" or references to coffee types, I did some simple measurements of queue operation times. This is what matters for a user, not what happens "under the bonnet".  ;D
I used two different folders, one with 299 jpegs and the other with 1256 jpegs. Also, multiple images per page were compared to single images per page because I knew that QU had extra background work to do when using a placement method like Optimal Spaced with multiple images on a page.
I also checked the times for adding a single image to the queue.
The PC is W7-67, Intel i7 3.6GHz, 6GB ram.
I  would agree that v214 was noticeably slower when 100 plus images were added to the queue, but it was still usable!
See table attached below where QU 2014.137 is compared to 2014.216
It can be seen that v216 is noticeably faster in many of the operations.

So, thanks to Mike for getting to the bottom of the issue and making this improvement to QU, regardless of the fact that many users will not see a difference because their queue sizes are small. You would not get this individual service from many software developers I could name.
Terry


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 03, 2014, 11:11:30 AM
I  would agree that v214 was noticeably slower when 100 plus images were added to the queue, but it was still usable!

Just to clarify, it was 213 that was the worst by far, and I was certainly not helping it by having my images on a networked drive. While Mike seems reluctant to say directly "there was a significant bug and I've fixed it", that is rather the impression I have :-)

But just as a matter of interest, you might like to try this experiment with different versions. Select freehand placement and add an image to a new page at the end of the queue. Edit that page and type a new value into one of the location boxes to move the image on the page. Nothing else, just move it a bit. 137 is instant, 213 is, err..., not! 214 and 215 were better but still not 137-speed. 216 I've yet to try because I had to do some actual work instead of playing with my photos.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: Terry-M on May 03, 2014, 11:39:35 AM
Hi,
Thanks for you comments, I'll try your other "test" when I get a moment.
Quote
While Mike seems reluctant to say directly "there was a significant bug and I've fixed it", that is rather the impression I have :-)
I would not have regarded that as a "bug" as such because it still did work and QU did not crash - an "inefficiency" would be more appropriate  ;)
Mike is never reluctant to improve the product where it benefits users and he will probe such queries and ask questions. Like he said, you did not really give any details of the process and end result regarding prints you were trying to achieve, step by step and in the end he had to deduce that from a poor quality video.
Don't feel too bad, it's a common problem that users do not give details of what they want to do and it takes a while to draw that out.
Enjoy your QU prints!
Terry


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: Terry-M on May 03, 2014, 11:59:13 AM
I might also add:
What other software would be so attentive, responsive and tuned to his users?
Terry


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 03, 2014, 12:09:38 PM
I would not have regarded that as a "bug" as such because it still did work and QU did not crash - an "inefficiency" would be more appropriate  ;)

If it was my own code, I'd call it a bug, but I accept that opinions can differ :-)

Quote
a poor quality video.

Ah, I didn't realise how bad that was; I just checked the first few seconds before uploading and they were fine. Later it does indeed become hard to tell what's going on but unfortunately nobody told me that :-(

Quote
Don't feel too bad, it's a common problem that users do not give details

Tell me about it! That's why I posted the video, thinking it would answer any questions about exactly what I was doing. Unfortunately the tool I would previously have used for screen capture doesn't work on Win7 and I was using a different one I'm not familiar with.

But anyway, I've now tried 216 and it's fine unless you have your images on a networked drive. Although it's no longer doing masses of unnecessary reading, it's still scanning the queue resulting in many network round trips. With 189 images in the queue, it takes about 8 seconds on my test machine to move an image on the page. 137 is near-as-dammit instant.

As it happens, the job I'm doing now can be done on the machine that holds the image files, but it's still a pity that there has been such a significant regression from 137. Perhaps it offers benefits that outweigh the cost for most people if not for me.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 03, 2014, 12:50:38 PM
If it was my own code, I'd call it a bug, but I accept that opinions can differ :-)

Feel free to call it a bug if it's your code.  :)  Me, I'll call it what it is in my own code: code optimization.

Quote
But anyway, I've now tried 216 and it's fine unless you have your images on a networked drive. Although it's no longer doing masses of unnecessary reading, it's still scanning the queue resulting in many network round trips. With 189 images in the queue, it takes about 8 seconds on my test machine to move an image on the page. 137 is near-as-dammit instant.

216 is faster than 137 in every way: reference Terry's timing chart above as I think he did a thorough job showing that there is not a single test where 137 is better!  216 is even faster on a network drive by my tests.  216 never reloads files as it caches the information locally.  So let me ask this: you're not doing something silly like picking your network drive as the application data folder are you (during install)?  That's the only way I can see you having a problem with performance: if you click Utilities, Explore Qimage Application Data in QU and that is pointing to a network drive.

All that said, when I have images on a network drive, I always copy them to the local drive to work with them.  IF I make any changes and need to update them after I'm done, I just copy only the changes back across the network to their original location.  QU's Flash Card Copy/Move function is perfect for that: you can update only what has changed on source/destination very efficiently.  I do this because I know how horribly inefficient network file I/O is.  Due to the way the OS handles data requests and the network packet overhead, even with a gigabit network file I/O is very inefficient so if you know you'll be working with multiple files, the local copy is a good idea anyway.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 03, 2014, 03:29:09 PM
216 is faster than 137 in every way: reference Terry's timing chart above as I think he did a thorough job showing that there is not a single test where 137 is better!

Well I've got a test that shows exactly that!

Actually, it's not a 'test' as such, it's the real job I'm trying to do.

Quote
216 never reloads files as it caches the information locally.

It's not reloading files, but it's still doing network I/O. Here's the scenario: Last page of my job, with 189 images in the queue, in the edit page function. I click on the procmon start-capture button, click back on Qimage window and enter '0' into the left location box. When Qimage finally finishes the move I stop the capture.

Result is that 137 issues 1,085 I/O calls for network files, 216 issues 4,633. Now none of these are reads in either case, but 216 still does over four times as many.

What happens with 137 is that for all the image files not on the current page, it calls CreateFile(), QueryBasicInformationFile() and CloseFile() which is not too unreasonable, then for each file on the current page it checks for an associated .flt 24 times, then checks the image file 13 times! That's pretty inefficient, but it's only for the last page so it's not so bad overall.

Now we compare 216: for images on previous pages it does 6 checks for a .flt and three metadata checks. For images on the last page, it does 19 .flt checks and 9 metadata cycles.

This doesn't sound like it should be faster and indeed it isn't!

Quote
So let me ask this: you're not doing something silly like picking your network drive as the application data folder are you (during install)?

Nope, nothing like that. It's just the image files that are remote.

Quote
All that said, when I have images on a network drive, I always copy them to the local drive to work with them.

For the work I'm doing, there's no need for network overhead to impose a noticeable penalty, and while 137 turns out to be less efficient than it could be, it doesn't really. 216 does. Sorry, but no matter how many times you tell me 216 is faster than 213, it's simply not so in the scenario above, and by a very significant margin: as I said, about 8 seconds for a simple move compared to barely 1s if that.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: ed_k on May 03, 2014, 03:46:56 PM
So I'm curious. If, in your opinion, QU post-137 is so bad, why do you continue to use it? Or, put another way, if 137 is so good why not continue to use that when the situation calls for it? Or another option is to use a competitor's product - a competitor who certainly would have held this one-on-one personal dialogue with you and fixed whatever is bothering you days ago. ;)


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 03, 2014, 05:08:53 PM
I'm sorry if anyone thinks I'm being unfair or unreasonable. I've been using Qimage for many years and it's still the best at what it does. For the moment, I am sticking with 137, but sooner or later there's likely to be some new feature I do want badly and I'd rather not have to take one step back while taking a different step forward.

So when Mike says "x is faster than 137" and it's plainly not, then what am I to do? Pretend that I see what I'm being told when I don't? Just quietly go away on the grounds that Adobe probably wouldn't have even bothered to respond at all?

There's a real issue here and I'm trying to be constructive in helping solve it, hence things like analysing the procmon logs to see where the bottlenecks are actually arising.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 03, 2014, 06:23:23 PM
So when Mike says "x is faster than 137" and it's plainly not, then what am I to do? Pretend that I see what I'm being told when I don't? Just quietly go away on the grounds that Adobe probably wouldn't have even bothered to respond at all?

Let's look at it another way.  Terry posted a very comprehensive 137 vs 216 performance test with actual times for both.  Every time on the list was equal to or faster than 137, almost all showed 216 significantly faster.  This mirrors what I see here, so until you can post actual numbers or I can find some way to reproduce your results, the only thing I know at this point is that I have confirmation from a third party to substantiate that 216 is significantly faster than 137.  So far you have none... or I have not found the right combination to unlock what is happening on your particular machine... or some combination of both.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 03, 2014, 06:36:46 PM
until you can post actual numbers

I have done exactly that. 8 seconds vs 1 or less. These are manually timed so a bit difficult to be more precise, but precision is hardly needed with that level of difference.

I've told you exactly what I did, I've told you what Qimage is doing from the Windows internal POV, I've offered you a VM copy of my test system (ok, it's a bit big to post here!). Tell me what more you want and if I can I'll do it.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 03, 2014, 08:48:51 PM
until you can post actual numbers

I have done exactly that. 8 seconds vs 1 or less. These are manually timed so a bit difficult to be more precise, but precision is hardly needed with that level of difference.

I've told you exactly what I did, I've told you what Qimage is doing from the Windows internal POV, I've offered you a VM copy of my test system (ok, it's a bit big to post here!). Tell me what more you want and if I can I'll do it.

Well, Terry did a lot more thorough timing and didn't just focus on one operation but rather than you repeating his tests, is there anything you can think of that might cause your network to be slower than normal?  Every single operation you try with images on a local drive is faster in 216 by a significant margin.  And when I test my own network, the margins are smaller but 216 is still as fast or a little faster.  So the only thing I can think of is something out of the ordinary like maybe you are connected to a wireless computer that has a low signal and packet loss, or there is something causing your network to have more overhead than usual.

I do have one more thing I'm going to do which should speed up network access by removing some file existence/date checks but without knowing why your network is acting differently than mine, I'm not sure how much impact that will have.

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 03, 2014, 10:11:54 PM
It's a GbE network and the remote disk is an SSD. File transfers can happily max out the link at a solid 100+MB/s.

ISTM it's the round-trip latency that kills performance. Are you telling me that in your tests you don't see a factor of 4.5 increase in I/O ops from 137 to 216?

Quote
Well, Terry did a lot more thorough timing and didn't just focus on one operation

But the operation I'm focussing on is the one with problems, not the many without! I'm not for a moment saying that there have been no gains in performance generally, merely that there have been significant losses in an area that affects me directly. Those losses have been reduced in the progression from 213 to 216 but not eliminated.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 04, 2014, 12:23:51 AM
OK.  Thanks.  Well, I always say... if one person has a problem, however uncommon, there will be more.  So I'll keep looking for more ways to squeeze out more performance.  :)

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 04, 2014, 12:49:27 AM
Thanks for that.

True or not, I've had the impression so far that you don't think my concerns are legitimate. Now I fully appreciate that there can be issues that don't affect most people and therefore aren't top of the priority list, but that's a very different thing to suggesting that the issues don't exist.

Let me just reiterate: I'm a software developer myself and I know full well that customers can have problems that are near-impossible to replicate. Lordy, do I know that! And sometimes it's true that they're complete idiots and everything they say is at best irrelevant and at worst a blatant lie!

I'm trying very hard to convince you that I'm not in that category. I've written file system drivers for Windows - indeed, entire file systems for proprietary OSs - and when I say that a large number of redundant operations are happening, it's not because I'm stupid and wrong.

Now sure, there are times when it's quicker to do something unnecessarily than work out whether it's necessary or not: BTDTGTTS! But I'm sorry to have to say this, but I've had the strong impression that I've almost been called a liar rather than being told that unfortunately my use case has had to suffer for the greater good.


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: Terry-M on May 04, 2014, 07:19:33 AM
Quote
Well, Terry did a lot more thorough timing and didn't just focus on one operation
Some final extra timings I did with 2014-216
I reduced the folder of 299 jpegs to 200, close to the 189 that steveren was using.
Loading the 200 to an A3 page with a size of 6x4" and Optimal spaced was almost instant, 1 second at the most.
I did the same with raw images by adding successive folders to the queue until there were 300. Again, each successive addition of a batch (~ raw 60 images) was almost instantaneous.
It was suggested to do this test:
Quote
Select freehand placement and add an image to a new page at the end of the queue. Edit that page and type a new value into one of the location boxes to move the image on the page
Again, with v216, the move was done in a flash, too short to time.
The results speak for themselves: v216 is OK  8)
Terry


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 04, 2014, 10:20:55 AM
The results speak for themselves: v216 is OK  8)

It is not ok for me, and if it's ok for you then there is clearly something different about what you and I are doing and/or our test environments. I would like to work out what that is, not just hypnotise myself into believing my problems are imaginary.

"It doesn't do that here" is an experience that every professional software developer knows well. It does not mean there is no problem.

Let me spell out some more details: I have a custom 295x295mm page, print-to-file set, and I'm placing images freehand. The intent is to create pages for uploading to an online print service to make a photobook. Pages generally have around 5-6 images, just less than 6x4 (147.5x98.4 mm) or submultiples. The images are JPEGs with a resolution that works out to 600dpi at the print size. They are held on an SSD on another machine connected via a Gbe network.

If you can duplicate this configuration and still get instant response, I'd be really interested to see your procmon log. There is no doubt that in my tests, Qimage is doing a lot of redundant I/Os. It may be that this is a red herring: they're not the cause of the slowdown. It may be that it doesn't do them if some other condition applies. Whatever it is, I'd like to know!


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: Terry-M on May 04, 2014, 12:31:39 PM
Quote
They are held on an SSD on another machine connected via a Gbe network
Mike has already given comments and advice on using a network, see reply #25  ::)
Quote
http://ddisoftware.com/tech/qimage-ultimate/severe-performance-loss-somewhere-between-2014-137-and-2014-210/msg15936/#msg15936
Last paragraph. Your problem seems to be your network and not at all related to QU because QU works fine here (edit after reply #39  :-[) even when images are on a USB2 drive connected to the PC.
Terry


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: Terry-M on May 04, 2014, 12:55:30 PM
About using QU.
Quote
I have a custom 295x295mm page, print-to-file set, and I'm placing images freehand. The intent is to create pages for uploading to an online print service to make a photobook. Pages generally have around 5-6 images, just less than 6x4 (147.5x98.4 mm) or submultiples.
One "trick" you could use is to deal with 1 or 2 pages at a time and save each as a Job. In that way you will limit the number of images that have to be processed at one time and probably make it easier to organise the book. When the whole book pages are all complete you can then process each page set.
Although I think the above is the better way in your case, if you wanted to process all pages at once, save as a Session so that when recalled, you can append each session one at a time to make the complete book. Make sure the P2F is set before you recall the sessions.
I regularly make "book" or "album" pages for my own records and do use the latter method when printing more than a few pages.
Terry


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 04, 2014, 01:17:21 PM
Now sure, there are times when it's quicker to do something unnecessarily than work out whether it's necessary or not: BTDTGTTS! But I'm sorry to have to say this, but I've had the strong impression that I've almost been called a liar rather than being told that unfortunately my use case has had to suffer for the greater good.

Gosh... not what I was going for: the liar or idiot angle.  :(  It's obvious you know what you are doing by your diagnosis/suggestions.  Since you use some of the same tools I do, I think we got hooked in just repeating what we are seeing which was different on our systems.  I worked on it last night and found something.  I was able to repeat a slowdown with 216 by putting one of my laptops on my guest network.  With things going through the network via the router (as opposed to the LAN which uses a switch), file operations were orders of magnitude slower and 216 was actually slower than 137 in that situation.  Not as slow as what you were seeing but I suppose many factors including image content could affect that.  So, having something to go on and a platform with which to test, I did a lot of things in 217 and it absolutely flies!  I added enough images to the queue to get a 10 second delay when adding/moving an image on the last page in 216 and in 217 it is instantaneous (unmeasurable via human hands).  It's in testing now.

Thanks for your feedback in this thread and for sticking with me!

Mike


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 04, 2014, 08:59:17 PM
Sounds good! I look forward to trying out 217 :-)


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: steveren on May 05, 2014, 07:02:59 PM
YAY! 217 rocks!

Well done and many thanks :-)


Title: Re: Severe performance loss somewhere between 2014.137 and 2014.210
Post by: admin on May 05, 2014, 08:22:43 PM
YAY! 217 rocks!

Well done and many thanks :-)

Thank you for your assistance!

Mike