Summary: slow C on solaris 2.7

From: Martin Meadows (PZXKYS@atdva3.atd.gmeds.com)
Date: Tue Oct 17 2000 - 06:57:38 CDT


Here's the summary I owe everyone. Sorry it took a week to produce it.
Also, I apologize for posting the question since it wasn't an urgent
sysadmin issue as some pointed out. Even so, it drew a lot of response
and seemed to be of interest. The list of those who replied (below)
is in no particular order. Thanks for the excellent help!! Sorry I didn't
respond to each of you individually. The concensus is that we are dealing
with a caching issue.

Marty Meadows

Here's the original question:

> Here is a fully functional C program which runs on Solaris 2.7 (compiled
> with a Sun C compiler) which counts the number of lines in a data file.
>
> It takes about 10 minutes to run initially, but then if you run it again
> immediately it runs in about 3 seconds thereafter.
>
> WHY?

From: David Mitchell <davem@fdgroup.co.uk>
From: Dan Lowe <dan@tangledhelix.com>
From: Ric Anderson <ric@Opus1.COM>
From: blymn@baesystems.com.au (Brett Lymn)
From: Tom Crummey <tom@ee.ucl.ac.uk>
From: "Ken Robson" <ken@robson.net>
From: Todd Herr <therr@va.rr.com>
From: Tim Carlson <tim@santafe.edu>
From: David Evans <daevans@us.Oracle.com>
From: Frank Smith <frank@artair.com>
From: David Foster <foster@dim.ucsd.edu>
From: mike.salehi@kodak.com
From: William Hathaway <wdh@ftope.com>
From: "Bruce R. Zimmer" <isdfgbrz@all-phase.com>
From: thadm@oregonian.com
From: Igor Schein <igor@txc.com>
From: Scott McCool <smmccool@aethersystems.com>
From: "Erin Jones" <erin@younetwork.com>
From: Dan Brown <brown@obscure.org>
From: Jay Lessert <jayl@latticesemi.com>
From: Hendrik Visage <hvisage@is.co.za>
From: Walter Reed <walter.reed@redherring.com>
From: James Ashton <James.Ashton@syseng.anu.edu.au>

------------------------------------------------------------------------
1. Most likely because the first time the file is read from disk
(or over the network?), and subsequent times the file is cached in
system memory.

2. Why not just use 'wc -l'
(or perl -e '$i++ while (<>); print "$i\n"')

3. What has this got to do with urgent system admin problems?

---------------------------------------------------------------------------
Because of the filesystem cache - if you just used a file, it will still be
in the filesystem cache and won't have to be fetched from disk again.

Just curious - it this just something you're writing to write it, or is the
"wc" utility too slow for what you want to do?

---------------------------------------------------------------------------
This is not really an appropriate question for Sun Managers, but I
shall answer you anyway....

More than likely the speed up is because the entire file is in the
buffer cache and is being read from memory instead of being peeled
from disk again - this is feasible because the total size of the file
is fairly small (less than a few megabytes according to your
comments). If there were lots of files being read/written at the same
time this test was run then you would probably see numbers closer to
the initial run.

---------------------------------------------------------------------------
I would guess the data file is on a busy disk, and thus is slow to
load. Once read, it is sitting in a ram cache, so a second execution
(if done soon enough) takes very little time.

I'm also presuming the numbers mentioned are wall clock times, not CPU
times.

-----------------------------------------------------------------------
Your problem sounds like a caching issue. Perhaps the data file is on
a cachefs and it's taking a long time to read across the network on the
first occasion. Alternatively, maybe the data is on an automounted
filesystem and some configuration issue is causing the initial mount to
take a very long time. You might try

        truss count.exe

and watch where your program is spending all it's time. Also try to
use `wc' to do the job and see if it suffers from the same problems.
Try count.exe and wc alternately to see how that affects things.

You really need to let us know more about your local config before we
can help any further. Mainly, what kind of filesystem is used to store
the data file and the program? Is your machine networked? What sort
of system load is present?

-----------------------------------------------------------------------
My guess is that your Ultra 30 is IO bound. Once the file is read, it's cached
in RAM so the second run is fast.

Try the simple "wc" program which does the exact same thing and see if you
have the same results - make sure your file isn't cached of course.

While you are running your command, run iostat -nx 1 in another window.
See what your wsvc_t and %w, %b numbers are. If wsvc_t is much over 10
on a regular basis, you are IO bound. The first iteration of iostat
gives max over time output, which isn't very useful.

-----------------------------------------------------------------------
Most probably because things are cached/buffered in RAM (Whic you
might have plenty off ;^)

Wouldn't classify this as a candidate posting based on the policy
document at the bottom either ;^)

-----------------------------------------------------------------------

If /usr/mfg_script/list_all_files is read over a slow network link
(or if it is pathologically slow to read for some other reason), you'll
see this kind of behavior; the second time you run, the file is
already cached in local RAM.

The difference will look even worse if the host is running large
processes (that have to be paged out) or doing a lot of file
I/O (potentially ditto) at the time.

If this is a case, a 'vmstat 5' running at the same time will be
illuminating; watch pi/po/sr.

-----------------------------------------------------------------------

Solaris caches as much data as it can, and, there's likely caches
in every io interface and ever disk as well.

Also, you might check if there's other mitigating factors... like,
is the data on an NFS share? Again Solaris will do a ton of caching.

-----------------------------------------------------------------------
this has to do w/ solaris' memory allocation. the first run it loads
everything necessary into memory. when you close the prog/it finishes the
memory is released but not reclaimed until it is needed again. if you run
again your prog already has all the necessary pieces loaded into memory and
runs much more quickly. check out adrian's newsletter at sunworld.

-----------------------------------------------------------------------

I compiled your program with gcc and ran it on a file consisting of the
output of "ls -lR /" concatenated together to form a 1,157,760 line file...
It took very little time to run. Compiler arguments were just "gcc -o count
count.c".

Output from "time ./count" shows that it took 1.948 seconds. Output from
"time wc -l /tmp/afile" shows that it took 3.180 seconds.

Did you try running wc -l? We can assume there aren't any bugs in that, i
guess...

It's been awhile since i did much C, but I didn't see anything majorly wrong
performance wise... Are you running out of memory or doing a lot of
swapping? My guess would be running out of resources since you're
manipulating a 600 K-line file... The E450 I'm running this on has a
gigabyte of RAM plus a hefty amount of swap space.

Did you try "wc -l" and compare it?

-----------------------------------------------------------------------
You must be reading a huge file. The 2nd time you run it, it's
already cached, so it runs much faster.

-----------------------------------------------------------------------
Probably because the file is still in the filesystem cache when you run
it a second time...

-----------------------------------------------------------------------
The reason is because the first time you run the program, it needs to read
the contents of the file into ram in order to read through the file. Solaris
will not flush a disk block out of RAM unless it requires the space for
something else. The next time you run the program, the file is already
memory resident, and so it does not require disk access to read the file.
Hence the faster speed.

-----------------------------------------------------------------------
I suspect a lot of the performance difference is that the data file is
cached in memory after the first access. This would especially be true if
you are accessing the data file via NFS.

-----------------------------------------------------------------------

     All the data will be cached at that point. I think the 10 minutes is a
bit high and you may improve it by
moving the data to /tmp

-----------------------------------------------------------------------
Probably disk caching I would imagine. Try running both invocations
using 'truss', it will list system calls and such and might provide
insight into this.

And is /usr/mfg_script a local directory, or NFS mounted? That would
be another source of slowness.

-----------------------------------------------------------------------
How long does it take to do 'wc -l /usr/mfg_script/list_all_files' ?
It sounds like it is taking a very long time to read the file the first
time, but since Solaris keeps files buffered in memory subsequent runs
run normally.
   If the file is NFS mounted I'd look for a networking problem (such as
a duplex mismatch).
   If wc -l is always fast, then it may be the linker is having problems
loading someting your program needs, especially if any libraries are NFS.

-----------------------------------------------------------------------
Which verision of Sun's compilers are you using?

Why are you using the "-xs", I can't see why you
need it and it can only slow things down. The man page is quite
clear about it. I mean you are opening a datafile and but your not
using any dbx routines and if you were the -g flag is sufficient
these days. This _may_ be why its slow to load initially and the
text segments may still be in memory for the subsequent runs if
there is enough resources on the machine.

My best guess.

-----------------------------------------------------------------------

NFS cache

-----------------------------------------------------------------------
The following is just wild speculation and may bear no resemblance
to the truth...

I'm guessing that perhaps the first time you run it, the roughly
91.5MB (or larger) file (610,000 lines times 150 chars/line) needs
to be loaded into memory from disk, and that may take a while on
your system. Your subsequent immediately after run may occur when
the file is still in memory. Solaris does some creative things
with memory allocation, in that no longer used chunks of memory
are marked as free but not actually freed until they're needed by
another process.

Run "truss count.exe" just to see what's happening during your
runs; that may provide some clues.

-----------------------------------------------------------------------
At a guess without looking at the code, the first time you run it, the data
file is not cached in memory and has to be fetched from disk, if you run it
again quickly enough then the file will still be cached and it runs that
much faster...

How big is your data file and how badly hammered are your disks?

-----------------------------------------------------------------------

Disk buffer?

When you run the program it loads as much of the file you are processing
into memory as it can. The second and subsequent times, it doesn't
have to do that.

That's just one possible reason...

------------------------------------------------------------------------

Here's the C source:

/* ****************************************************************** *
 * PROGRAM - count.exe.c *
 * ****************************************************************** *
 * This program is used to count the entries in: *
 * /usr/mfg_script/list_all_files *
 * There are more than 610,000 lines of variable length in the *
 * data file. *
 * The longest record is (currently) 290 characters. *
 * ------------------------------------------------------------------ *
 * The workstation is a SPARC Ultra 30, running Solaris 5.7 *
 * ------------------------------------------------------------------ *
 * The progam is comiled using: *
 * /opt/SUNWspro/bin/cc -g -xs -o count.exe count.exe.c *
 * ------------------------------------------------------------------ *
 * Initially, it takes approximately 10 minutes to execute. *
 * Subsequent attempts complete in under 5 seconds. *
 * ****************************************************************** *
 * 2000-Oct-04 PMS: Created. *
 * ****************************************************************** */

#include <stdio.h>

#define MAXCHR 1024

/**********************************************************************/
void main()
/*+*******************************************************************/
{
 char Record[MAXCHR],DataFile[60];
 long cnt;
 FILE *d_file;
 /*+*******************************************************************/
 strcpy(DataFile,"/usr/mfg_script/list_all_files");
 /*+*******************************************************************/
 /*+**** Open Data File ****+*/
 /*+*******************************************************************/
 if ((d_file=fopen(DataFile,"r")) == NULL) {
   printf("Unable to open %s for reading!\n",DataFile);
   exit(1);
 } else {

 /*+*******************************************************************/
  cnt=0;
  printf("Counting Records...\n");

  while (fgets(Record,MAXCHR,d_file)!=NULL) {
   cnt++;
   if (cnt % 10000 == 0) printf("%6d Records\n",cnt);
  }
  printf("%d records in %s\n",cnt,DataFile);
 }
 fclose(d_file);
}/*+************************ END OF MAIN ******************************/

S
U BEFORE POSTING please READ the FAQ located at
N ftp://ftp.cs.toronto.edu/pub/jdd/sun-managers/faq
. and the list POLICY statement located at
M ftp://ftp.cs.toronto.edu/pub/jdd/sun-managers/policy
A To submit questions/summaries to this list send your email message to:
N sun-managers@sunmanagers.ececs.uc.edu
A To unsubscribe from this list please send an email message to:
G majordomo@sunmanagers.ececs.uc.edu
E and in the BODY type:
R unsubscribe sun-managers
S Or
. unsubscribe sun-managers original@subscription.address
L To view an archive of this list please visit:
I http://www.latech.edu/sunman.html
S
T



This archive was generated by hypermail 2.1.2 : Fri Sep 28 2001 - 23:14:20 CDT