Re: The significance of pbuf_flush messages. (fwd)

------- Forwarded Message

Date:    Tue, 30 Jul 2002 16:10:46 -0600
From:    Russ Rew <address@hidden>
To:      "Stonie R. Cooper" <address@hidden>
cc:      address@hidden,
         "Cannon, Declan" <address@hidden>, rkambic
Subject: Re: The significance of pbuf_flush messages. 


>To: Russ Rew <address@hidden>
>From: "Stonie R. Cooper" <address@hidden>
>Subject: Re: 20020730: The significance of pbuf_flush messages.
>Organization: Planetary Data
>Keywords: pbuf_flush-problem

Hi Stonie,

> I apologize for the question - but what does pbuf_flush signify?  Since 
> upgrading to 5.2, I see this with an ldmadmin tail:
> 
> Jul 25 18:41:18 helium pqact[691]: pbuf_flush 11: time elapsed   2.977440
> Jul 25 18:54:59 helium pqact[691]: pbuf_flush 11: time elapsed   2.531959
 ...
> Never mind . . . Declan found me the relevant information on the "time
> elapsed" messages.  This does infer, simply because I saw them very
> rarely in 5.1.4, that somehow 5.2 is slower . . . at least it seems to
> take longer than 1 second more often with 5.2 than with 5.1.4.  Or
> maybe it's the net session of alephone that's doing it . . . ;-)

I've discovered at least one possible reason LDM 5.2 might be slower
than LDM 5.1.4, and I've appended a patch to src/server/svc.c that you
could try to see if it makes a significant difference.

We had left in some debugging code that slow things down, due to a
call to the strlen() function in the argument that's evaluated for
every product even when not in debug mode.  A few other optimizations
got the time per product of this code down from 627 usec/product to
0.92 usec/product.

Thus for 100,000 products the new code uses about 0.09 seconds instead
of 63 seconds of CPU time (at least on my Sun-Blade-1000), but that
may still not be significant enough to explain the extra pbuf_flush
calls.  But please let us know if you get a chance.  If it works, we
may issue this as a patch, or maybe just roll it into the inevitable
5.2.1 ...

--Russ

Index: svc.c
===================================================================
RCS file: /upc/share/CVS/ldm5/server/svc.c,v
retrieving revision 1.86
diff -r1.86 svc.c
33,60c33,51
< int   olen, i, FOUND=0;
< char  *cpos=NULL, hostcat[HOSTNAMESIZE + HOSTNAMELEN + 4];
< static        char    SEPSTR[]="_v_";
< 
< udebug("origin_upstream origin: %d %s\0",strlen(origin),origin);
< 
< memset(hostcat,0,sizeof(hostcat));
< 
< i = 0; 
< while( ( FOUND == 0 ) && ( i + strlen (SEPSTR) < strlen(origin) ) )
<    {
<    if ( memcmp(origin+i, SEPSTR, strlen(SEPSTR) ) == 0)
<       {
<       FOUND = 1;
<       cpos = origin+i;
<       }
<    else
<       i++;
<    }
< 
< if(cpos != NULL)
<    {
<    cpos += 3;
<    strncat(hostcat,origin,cpos - origin);
<    strcat(hostcat,remote_name());
<    }
< else
<    sprintf(hostcat,"%s%s%s\0",origin,SEPSTR,remote_name());
---
>     int       olen;
>     char *cpos;
>     char hostcat[HOSTNAMESIZE + HOSTNAMELEN + 4];
>     static    char    SEPSTR[]="_v_";
>     static    int     sepstr_len = sizeof(SEPSTR) - 1;
>     const char* remotename = remote_name();
> 
>     hostcat[0] = '\0';
> 
>     cpos = strstr(origin, SEPSTR);
>     if (cpos != NULL) {
>       olen = cpos - origin;
>       strncpy(hostcat, origin, olen);
>     } else {
>       olen = strlen(origin);
>       strcpy(hostcat, origin);
>     }
>     strcpy(hostcat + olen, SEPSTR);
>     strcpy(hostcat + olen + sepstr_len, remotename);
62,68c53
< olen = strlen(hostcat);
< 
< if(olen >= HOSTNAMESIZE) olen = HOSTNAMESIZE-1;
< udebug("origin_upstream:  sizes %d %d   %d %s\0",HOSTNAMESIZE,olen, 
strlen(hostcat),hostcat);
< 
< memset(origin,0,olen+1);
< memcpy(origin,hostcat,olen);
---
>     hostcat[HOSTNAMESIZE] = '\0';
69a55
>     strcpy(origin, hostcat);
124c110
<        * in tact. 
---
>        * intact. 
126,128c112,115
<         char sp[HOSTNAMESIZE];
<         prod_info newinfo;
<         product newprod;
---
>       char sp[HOSTNAMESIZE + 1];
>       product newprod;
> 
>       strcpy(sp, prod->info.origin);
130,134d116
<         memset(sp,0,HOSTNAMESIZE);
<         memcpy(sp,prod->info.origin,strlen(prod->info.origin));
<         
<       udebug("hereis origin %d %s\0",strlen(sp),sp);
<       udebug("prod ident %s\0",prod->info.ident);
136d117
<       udebug("hereis origin back %s\0",sp);
138,144c119,125
<         newinfo.arrival = prod->info.arrival;
<         memcpy(newinfo.signature,prod->info.signature,sizeof(signaturet));
<         newinfo.origin = sp;
<         newinfo.feedtype = prod->info.feedtype;
<         newinfo.seqno = prod->info.seqno;
<         newinfo.ident = prod->info.ident;
<         newinfo.sz = prod->info.sz;
---
>       newprod.info.arrival = prod->info.arrival;
>       memcpy(newprod.info.signature,prod->info.signature,sizeof(signaturet));
>       newprod.info.origin = sp;
>       newprod.info.feedtype = prod->info.feedtype;
>       newprod.info.seqno = prod->info.seqno;
>       newprod.info.ident = prod->info.ident;
>       newprod.info.sz = prod->info.sz;
146,147c127
<         newprod.info = newinfo;
<         newprod.data = prod->data;
---
>       newprod.data = prod->data;
413c393
<         char sp[HOSTNAMESIZE];
---
>         char sp[HOSTNAMESIZE + 1];
415,416c395
<         memset(sp, 0, HOSTNAMESIZE); 
<         memcpy(sp,infop->origin,strlen(infop->origin));
---
>       strcpy(sp, infop->origin);
418,419d396
<       udebug("****comingsoon origin %d %s\0",strlen(sp),sp);
<         udebug("product id %s\0",infop->ident);
421d397
<       udebug("****check origin %s\0",sp);

------- End of Forwarded Message