rand@merrimack.edu (01/27/90)
In article <17198@kuhub.cc.ukans.edu>, SLOANE@kuhub.cc.ukans.edu (Bob Sloane) writes: > Perhaps what we need is some more information about what part of news is > taking up the most time. My intuition is that it is file system overhead > doing directory reads. Others seem to think that a lot of time is spent > processing NEWSRC. DEC has some tools for profiling the execution of an image > and finding out where it is spending its time. Could someone who has a > product like this run in on news and get some statistics on where news is > spending its time? I just got PCA and decided to give it a go. Since most use of NEWS, and hence where performance is an issue, is centered around reading, I profiled a typical (for me) reading session. When reading I tend to: a) Read registered groups sequentially b) When reading a group I scan down the directory with a keypad key defined as DOWN 18 and read items of interest (20-30%) c) After viewing all desired items I mark them all as read with a keypad key and do a SELECT/NEW bound to a keypad key d) goto a) The profile is based on CPU ticks spent on each line of code. Below are 2 sections. The first is a summary of percentage of cpu time spent in each routine (for those routines that were executed). The second section displays the actual lines of the 'worst' routines that had any significant cpu time (>.01%). I don't have a great amount of free time but if people send me code enhancements I'll try to profile them. Also, if anyone thinks the bottleneck is anything but computational (faulting, physical io) and thinks that code can be improved I can collect data on that bottleneck. Anyone else that has CSLG can do this too, PCA is free. (Read: I'm kind of busy, don't have the docs, and don't know c.) Hope this helps Rand P. Hall UUCP: {uunet,wang,ulowell}!samsung!hubdub!rand Merrimack College CSNET: rand@merrimack.edu N. Andover, MA 508.683.7111 Dukakis = 15% tax hike + $1.3 billion deficit ------------------------------ VAX Performance and Coverage Analyzer Page 1 CPU Sampling Data (2756 data points total) - "*" Data 95% Conf Bucket Name Count Percent Interval NEWSUTILITY\ map_items . . . . . . . 404 14.7% +/- 1.3% NEWS\ main . . . . . . . . . . 385 14.0% +/- 1.3% NEWSDISPLAY\ put_line . . . . . . . . 259 9.4% +/- 1.1% NEWSUTILITY\ set_level . . . . . . . 214 7.8% +/- 1.0% position_display . . . . 183 6.6% +/- 0.9% ga_exact_name . . . . . 162 5.9% +/- 0.9% gendate . . . . . . . . 128 4.6% +/- 0.8% NEWSDISPLAY\ do_display . . . . . . . 126 4.6% +/- 0.8% NEWSFILES\ open_groups . . . . . . 112 4.1% +/- 0.7% NEWSRTL\ c$alloc_tmp . . . . . . 98 3.6% +/- 0.7% NEWSUTILITY\ screen_map_dir . . . . . 89 3.2% +/- 0.7% NEWSRTL\ c$cks . . . . . . . . . 85 3.1% +/- 0.6% NEWSRC\ write_reg_file . . . . . 59 2.1% +/- 0.5% putl . . . . . . . . . . 49 1.8% +/- 0.5% read_reg_file . . . . . 47 1.7% +/- 0.5% NEWSDISPLAY\ start_header . . . . . . 39 1.4% +/- 0.4% NEWSUTILITY\ do_openi . . . . . . . . 34 1.2% +/- 0.4% NEWSSETSHOW\ check_access . . . . . . 32 1.2% +/- 0.4% NEWSREAD\ xrefs . . . . . . . . . 23 0.8% +/- 0.3% NEWSUTILITY\ create_keydefs . . . . . 20 0.7% +/- 0.3% NEWSRTL\ c$dsc . . . . . . . . . 18 0.7% +/- 0.3% NEWSUTILITY\ init_screen . . . . . . 15 0.5% +/- 0.3% NEWSRTL\ fgetl . . . . . . . . . 14 0.5% +/- 0.3% NEWSRC\ class_list . . . . . . . 13 0.5% +/- 0.3% NEWSDISPLAY\ end_header . . . . . . . 11 0.4% +/- 0.2% NEWSDIR\ do_dir . . . . . . . . . 10 0.4% +/- 0.2% NEWSDISPLAY\ put_parse . . . . . . . 9 0.3% +/- 0.2% NEWSUTILITY\ clear_err_line . . . . . 9 0.3% +/- 0.2% NEWSRTL\ c$rfi . . . . . . . . . 8 0.3% +/- 0.2% NEWSMOD\ read_mod_file . . . . . 7 0.3% +/- 0.2% NEWSFILES\ openfiles . . . . . . . 6 0.2% +/- 0.2% NEWSRC\ add_class_member . . . . 6 0.2% +/- 0.2% NEWSSITE\ call_mail_profile . . . 6 0.2% +/- 0.2% NEWSRTL\ s_to_lower . . . . . . . 5 0.2% +/- 0.2% NEWSUTILITY\ check_command . . . . . 5 0.2% +/- 0.2% do_refresh . . . . . . . 5 0.2% +/- 0.2% NEWSDIR\ dirnew_check . . . . . . 4 0.1% +/- 0.1% NEWSSKIP\ do_skip . . . . . . . . 4 0.1% +/- 0.1% screen_update_gread. . . 4 0.1% +/- 0.1% screen_update_iread. . . 4 0.1% +/- 0.1% NEWSUTILITY\ create_pb . . . . . . . 4 0.1% +/- 0.1% cur_down_itm . . . . . . 4 0.1% +/- 0.1% do_parse . . . . . . . . 4 0.1% +/- 0.1% NEWSFILES\ closefiles . . . . . . . 3 0.1% NEWSRC\ reg_context . . . . . . 2 0.1% NEWSSELECT\ do_select . . . . . . . 2 0.1% selnew . . . . . . . . . 2 0.1% NEWSSITE\ no_priv . . . . . . . . 2 0.1% site_get_env . . . . . . 2 0.1% NEWSUTILITY\ cli_catch . . . . . . . 2 0.1% cur_set_grp . . . . . . 2 0.1% noscreen . . . . . . . . 2 0.1% screen_cur_up . . . . . 2 0.1% NEWSMODE\ broad_trap . . . . . . . 1 0.0% edit_m_off . . . . . . . 1 0.0% no_broad_trap . . . . . 1 0.0% NEWSMOD\ moderator_address . . . 1 0.0% NEWSRC\ kill_read . . . . . . . 1 0.0% NEWSREAD\ item_update . . . . . . 1 0.0% NEWSUTILITY\ display_brdcst . . . . . 1 0.0% newsgroup_header . . . . 1 0.0% newsgroup_status_li ne . . . . . . . . . . 1 0.0% screen_cur_down . . . . 1 0.0% util_dir . . . . . . . . 1 0.0% ****************************** DISK$DISKA6:[RAND.TMP]NEWSDISPLAY_DO_DISPLAY.OUT;1 Percent Count Line NEWSDISPLAY\do_display\ 1.7% 46 7444: if (fstat(fd,&dispf_stat)) dispf_stat.st_size = 0 1.9% 52 7454: if (fstat(fd,&dispf_stat)) dispf_stat.st_size = 0 0.1% 4 7464: if (!(p1 = strchr(inpline,'\n')) && ((i = strle 0.4% 12 7492: } 0.4% 10 7493: fclose(fp); ****************************** DISK$DISKA6:[RAND.TMP]NEWSDPY_PUTLINE.OUT;1 Percent Count Line NEWSDISPLAY\put_line\ 0.2% 5 7123: smg$move_virtual_display(&sdid,&pid,&sdid_pas 0.1% 3 7146: smg$put_chars(&trailer_vd,c$dsc(mprompt),c$rf 6.4% 177 7149: smg$end_pasteboard_update(&pid); 1.2% 33 7150: status = smg$read_composed_line(&kid,&keytab, 0.6% 16 7303: smg$move_virtual_display(&sdid,&pid,&sdid_paste,c 0.5% 13 7307: smg$put_with_scroll(&sdid,c$dsc(s),0,0,0,0,0); ****************************** DISK$DISKA6:[RAND.TMP]NEWSFILES_OPEN_GROUPS.OUT;1 Percent Count Line NEWSFILES\open_groups\ 0.1% 2 7246: ga[++ga_size] = malloc(sizeof newsgrp); 0.3% 9 7252: *ga[ga_size] = newsgrp; 3.6% 98 7254: } ****************************** DISK$DISKA6:[RAND.TMP]NEWSRTL_C$ALLOC_TMP.OUT;1 Percent Count Line NEWSRTL\c$alloc_tmp\ 0.5% 14 6942: int size; 2.7% 75 6946: c$_tmp = malloc(size + 4); 0.3% 7 6947: *c$_tmp = c$_tmphead; 0.1% 2 6949: return(c$_tmphead + 1); ****************************** DISK$DISKA6:[RAND.TMP]NEWSUTILITY_GA_EXACT_NAME.OUT;1 Percent Count Line NEWSUTILITY\ga_exact_name\ 5.4% 149 8381: || (lens != strlen(n))) 0.1% 2 8388: if (ps == s) return(i); 0.3% 7 8389: } ****************************** DISK$DISKA6:[RAND.TMP]NEWSUTILITY_GENDATE.OUT;1 Percent Count Line NEWSUTILITY\gendate\ 0.1% 2 7987: char *gendate(i) unsigned int i; 4.4% 120 7989: strncpy(fmt_date,ctime(&i),24); 0.1% 2 7991: fmt_date[7]='-';fmt_date[8]=fmt_date[22];fmt_date[9 0.1% 2 7992: fmt_date[10]='\0'; ****************************** DISK$DISKA6:[RAND.TMP]NEWSUTILITY_MAP_ITEMS.OUT;1 Percent Count Line NEWSUTILITY\map_items\ 0.1% 2 8574: gap->grp_ia = malloc((gap->grp_iasize + 1) * (siz 0.6% 16 8587: while (sys$get(&itmrab) & 1) { 0.4% 11 8596: gap->grp_ia[++gap->grp_count] = newsitm; 13.4% 370 8597: } ****************************** DISK$DISKA6:[RAND.TMP]NEWSUTILITY_POSITION_DISPLAY.OUT;1 Percent Count Line NEWSUTILITY\position_display\ 1.5% 42 8754: if (refresh) c$cks(smg$end_pasteboard_update(&pid 5.1% 141 8755: smg$move_virtual_display(vd,&pid,cp,c$rfi(1),0); ****************************** DISK$DISKA6:[RAND.TMP]NEWSUTILITY_SCREEN_MAP_DIR.OUT;1 Percent Count Line NEWSUTILITY\screen_map_dir\ 0.1% 4 8772: smg$erase_display(&grp_vd); 0.1% 2 8776: if (ga[g]->grp_display_indx) { 0.9% 24 8782: smg$put_chars(&grp_vd,c$dsc(err_oline),&sg,c$rf 0.1% 2 8788: smg$change_rendition(&grp_vd,&sg,c$rfi(12),c$ 0.2% 5 8789: if (ga[g]->grp_unread) smg$change_rendition(& ****************************** DISK$DISKA6:[RAND.TMP]NEWSUTILITY_SET_LEVEL.OUT;1 Percent Count Line NEWSUTILITY\set_level\ 0.1% 2 8874: int l; 0.1% 2 8884: smg$unpaste_virtual_display(&sdid,&pid); 0.1% 2 8885: smg$unpaste_virtual_display(&shdid,&pid); 0.8% 21 8928: smg$create_virtual_display(c$rfi(gap->grp_iav 0.1% 3 8930: fdate = gendate(iap[i].itm_date); 4.5% 125 8931: sprintf(err_oline," %-5d %c %-*.*s %6d %s 1.7% 46 8932: smg$put_chars(&gap->grp_iavd,c$dsc(err_olin 0.1% 3 8940: } 0.1% 2 8961: c$cks(smg$paste_virtual_display(&itm_header_vd,&p ****************************** DISK$DISKA6:[RAND.TMP]NEWS_C$CKS.OUT;1 Percent Count Line NEWSRTL\c$cks\ 3.0% 84 7000: free(c$_tmphead); ****************************** DISK$DISKA6:[RAND.TMP]NEWS_MAIN.OUT;1 Percent Count Line NEWS\main\ 0.1% 4 6989: fclose(fp); 0.1% 3 6995: smg$erase_display(&trailer_vd,c$rfi(1),c$rfi(6) 10.7% 294 7004: smg$end_pasteboard_update(&pid); 2.8% 77 7007: &response_length,((screen_active) ? (&trail (Did anyone actually read all of this? ;-)
toon@vax1.sara.nl (01/30/90)
In article <18387.25c07443@merrimack.edu>, rand@merrimack.edu writes: > > I just got PCA and decided to give it a go. Since most use of NEWS, and > hence where performance is an issue, is centered around reading, I profiled > a typical (for me) reading session. When reading I tend to: > > a) Read registered groups sequentially > b) When reading a group I scan down the directory with a keypad key > defined as DOWN 18 and read items of interest (20-30%) > c) After viewing all desired items I mark them all as read with a > keypad key and do a SELECT/NEW bound to a keypad key > d) goto a) .. follows a lot of numbers ... > (Did anyone actually read all of this? ;-) A collegue and I did a subset of this already in November and subsequently mailed the results to Geoff (we were using ANU-news 5.8 then). We never heared of it since. In our experiments ga_exact_name was the culprit, so we changed it to do the strcmp inline, which sped up this routine by about 50 %; by now the problem is in the index evaluation ga[i]->grp_name, which we can't change without redesigning ANU-news fundamentally. Of course, in our case also the RMS calls were important. I even mentioned to Geoff changing the NEWS.GROUPS file into a global section and mapping it once, at the beginning of a news session. The solution to use RMS global buffers is of course a better one, because it doesn't require rewriting ANU-news. BTW, before all this, I'd already modified the ANU-news sources to use &(constant expression) wherever Geoff used c$rfi(constant expression) in function argument lists. See for this (non-ANSI) trick the VAX C manual (page 14-11 for VAXC 2.4). Therefore in our measurements c$alloc_tmp doesn't show up. With this modification you save up to four function calls per occurrence (very frequent in screen management routine calls) and a lot of (expensive) heap space management (ANSI folks, are you listening ?). -- Toon Moene, SARA - Amsterdam (NL) Internet: TOON@SARA.NL Disclaimer: Don't need one. Real Programmers (as opposed to Quiche Eaters) are not afraid to claim.
gih900@CSC1.ANU.OZ.AU (Geoff Huston) (02/01/90)
>I just got PCA and decided to give it a go. Since most use of NEWS, and >hence where performance is an issue, is centered around reading, I profiled >a typical (for me) reading session. When reading I tend to: > > .... > >(Did anyone actually read all of this? ;-) yes - thanks for that Geoff