[ic] More Results *VERY* Slow

Bryan Gmyrek interchange-users@icdevgroup.org
Thu Oct 17 12:37:01 2002


> > I am running Interchange 4.8.6 on it's own RedHat Linux 7.3 
> > server with a 
> > pentium III, etc... Mysql for the products, etc; sessions 
> > and tmp files 
> > are in the /tmp directory under the catalog dir. In general 
> > it is pretty 
> > fast, typical search times are only a couple of seconds to return 
> > thousands of results (the catalog has over 3,000 items). 
> > 
> > However, the 'more results' at the bottom of a search is *extremely* 
> > slow... more than 40 seconds even on a fast internet connection (where 
> > performing the search and displaying 40 results with images 
> > only took 5 
> > seconds!). Is there something, anything, that I can do to 
> > speed this up??
> 
> Aaron Hazelton wrote:
> 
> what do your error logs say? usually there is some sort of an error 
> being written in the 'lag' time.
> 
> Bryan Gmyrek wrote:
> 
> Woah, I don't know how I missed this. Thanks for making me look again! Here is the error: 
> /cgi-bin/store/scan/MM=a65e309bf359fa4faa88477fb035a93c:20:39:20 search error: Object saved wrong in /opt/interchange/catalogs/store/tmp/K/ KY38oYbT.a65e309bf359fa4faa88477fb035a93c for search ID KY38oYbT.a65e309bf359fa4faa88477fb035a93c. 
> What can I do? The permissions of the tmp files is posted below John's post along with a ton of other info I collected before noticing this error.
> Recently I think I deleted all of the tmp files by doing a rm -rf * in the /opt/interchange/my-catalog/tmp directory... could this have anything to do with it?
> 
> John Young wrote:
> 
> In addition to looking at your logs (both for interchange and httpd), as Aaron 
> mentioned), you can look at file I/O performance to/from /tmp. By default, 
> Interchange handles more-list data by storing the entire initial search results in 
> a file under /tmp. The file will be in a subdirectory named according to the 
> first letter of your session id. The file name will be your session id + . + the 
> MM= value you see in your more-list links. Something like (session id = xJayxmUu): 
> 
> /tmp/x/xJayxmUu.45683d15f649e6aa2de84ebd5e1a9392 
> 
> If you have a broad search with millions of products, the file can be large. You 
> may wish to verify how quickly you can read files of that size from /tmp. If 
> /tmp is on a busy drive, if the controller is IDE instead of SCSI, if your search results 
> are multiple gigabytes, you could have slow more-list performance. For 
> very high traffic sites, it can make sense to have /tmp on a separate disk or 
> some other similar strategy. Aaron's suggestion of checking your logs is 
> the first step, though. 
> 
> 
> Bryan Gmyrek wrote:
> 
> I will leave the following tacked on for posterity or because maybe it's useful to you, wrote this before I noticed that error: 
> OK, let me give my server information. 
> It is a dedicated server with a 
> HARDWARE 
> Pentium III at 434 MHz 
> 20 Gig IDE hard drive 
> 256 Megs of memory 
> SOFTWARE 
> Red Hat Linux 7.3 
> Perl 5.6.1 
> Interchange 4.8.6 using Mysql database (3,500 entries in products database) 
> The only other thing running on the server is a pretty lifeless PHP message board. 
> The store handles about 5,000 page views a day, about 1,300 are 'scan' pages. 
> I don't know anything about suexec but I susupect that it is running and I didn't specify this in the catalog setup. 
> 
> Now, here is the interesting part. I did a split screen with interchange on one side an a ssh session with top running on the other. 
> I searched for 'flowers' which returned about 700 results (search only takes a few sec) 
> Also searched for 'lighthouses' which returned about 70 results 
> Here are the results in terms of memory usage and cpu usage while waiting after pressing the more results link for each case 
> (during referrs to during the search) 
> 
> FLOWER SEARCH (700 RESULTS - PRESSED NEXT) 
> interchange before: CPU=0.0%, MEM=8.0% 
> interchange during: CPU=60%, MEM=10% 
> mysql before: CPU=0.0%, MEM=0.0% 
> mysql during: CPU=35%, MEM=4.0% 
> elapsed time: about 30 seconds (in the middle of the night.. in the day it is more like 50 sec) 
> 
> LIGHTHOUSE SEARCH (70 RESULTS - PRESSED NEXT) 
> interchange before: CPU=0.0%, MEM=8.0% 
> interchange during: CPU=30%, MEM=10% 
> mysql before: CPU=30%, MEM=9.0% 
> mysql during: CPU=10%, MEM=1.0% 
> elapsed time: 6 seconds (at night) 
> (some numbers rounded) 
> 
> So the CPU is being almost totally chomped with only 700 results! 
> 
> As John suggested I checked the temp files (the entire /tmp directory was only about 13 megs after a couple days of accumulating tmp stuff) 
> It took me less then a second to open them in vi: 
> interch@host [/opt/catalogs/art/tmp/N]# ls -l 
> total 64 
> drwxrws--- 2 interch interch 4096 Oct 16 04:05 ./ 
> drwxrwsr-x 63 interch interch 4096 Oct 15 23:23 ../ 
> -rw-rw---- 1 interch interch 1013 Oct 14 14:32 Nmebj9SD.0c66d5e77931c8ef99c3742c776ce84c 
> -rw-rw---- 1 interch interch 2151 Oct 13 19:17 Nn9Vd9HG.74695eac48ab5ea134e59a212d6a201a 
> -rw-rw---- 1 interch interch 917 Oct 13 19:17 Nn9Vd9HG.8cbaaf41a2c26ef08f6ab9a1514a5a53 
> -rw-rw---- 1 interch interch 2241 Oct 15 14:50 NW9tTM9f.6d8f4e3368fc4531db22fb663bd584f5 
> -rw-rw---- 1 interch interch 920 Oct 15 14:50 NW9tTM9f.8cbaaf41a2c26ef08f6ab9a1514a5a53 
> -rw-rw---- 1 interch interch 12175 Oct 16 04:00 NYssqCJm.0a974b24296210811812753e62928282 
> -rw-rw---- 1 interch interch 12022 Oct 16 03:05 NYssqCJm.1b826d542f0de86458991b8975e3e61f 
> -rw-rw---- 1 interch interch 4349 Oct 16 03:12 NYssqCJm.1d2f5c648864fcc54851530e911da530 
> -rw-rw---- 1 interch interch 2800 Oct 16 03:13 NYssqCJm.a28965abb52271284ae9b02bf2afde53 
> interch@host [/opt/catalogs/art/tmp/N] 
> 
> In the case of the flowers the first more result was NYssqCJm.0a974b24296210811812753e62928282 
> Looking at the file in vi I can't imagine why it would take so long to read. 
> 
> So it sounds like this is not a 'standard' problem since I think the server is up to snuff for one relatively small (not millions of products or users) catalog.
> _______________________________________________

Found this in the archives:

> [ic] search error. Object saved wrong 
> 
> Mike Heins mikeh@minivend.com
> Fri, 2 Feb 2001 06:42:09 -0500 
> 
> Previous message: [ic] search error. Object saved wrong 
> Next message: [ic] if statements that check who's logged in. 
> Messages sorted by: [ date ] [ thread ] [ subject ] [ author ] 
> 
> 
> Quoting Ron Phipps (rphipps@reliant-solutions.com): 
> > > > hcns003.zaq.ne.jp iIVFppre:ne.jp - [02/February/2001:16:42:06 +0900] 
> > > > outdoor-w 
> > > > /cgibin/outdoor-w.cgi/scan/MM=e83069a8c5b65ade3baaab0919e20bf4:20:39:20 
> > > > search error: Object saved wrong in 
> > > > /mnt/web/guide/ayayu.com/catalogs/outdoor-w/tmp/i/iIVFppre.e83069a8c5b65 
> > > > ade3baaab0919e20bf4 for search ID 
> > > > iIVFppre.e83069a8c5b65ade3baaab0919e20bf4. 
> > > 
> > > I am guessing this is an I/O error in Storable or Data::Dumper 
> > > caused by the ongoing problems with Perl, signals, I/O, and FreeBSD. 
> > 
> > We've recieved these same errors on a RedHat x86 box running IC. It may be 
> > more wide spread then FreeBSD. 
> 
> IF someone (running RedHat and Perl 5.6.0 all latest modules, need binary 
> compatibility on file) can attach an offending file, I will take a look 
> at it. 
> 
> I will need to know whether you are running Storable, as I suspect 
> you are. If you are not, or are not running the very latest version, 
> get updated as you *will* get these errors with binary data. 
> 
> This would be exacerbated with frequent Unicode characters or other 
> binary data -- and there are a few Unicode bugs in Perl which are being 
> touched up for 5.6.1, so that can be it too. 

Upgraded Storable to 2.05... rebooted the entire server... nothing changed :(

Now, something that is really weird is the fact that it seems like sometimes the error is written and sometimes it isn't.  When I tried it late at night I could see the error messages but in the middle of the day I reproduce the thing which causes the error and yet there is no change in the error log (which is why it was not included in my first message ;)  Anyway, I digress.  Here is an offending file as Mike requested:
http://www.gmyrek.us/temp/tjfi62Tq.0a974b24296210811812753e62928282

Thanks for any advice.

Bryan.