[ic] More Results *VERY* Slow

Bryan Gmyrek interchange-users@icdevgroup.org
Wed Oct 16 04:37:10 2002


> I am running Interchange 4.8.5 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.