gprof.texi 91 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468146914701471147214731474147514761477147814791480148114821483148414851486148714881489149014911492149314941495149614971498149915001501150215031504150515061507150815091510151115121513151415151516151715181519152015211522152315241525152615271528152915301531153215331534153515361537153815391540154115421543154415451546154715481549155015511552155315541555155615571558155915601561156215631564156515661567156815691570157115721573157415751576157715781579158015811582158315841585158615871588158915901591159215931594159515961597159815991600160116021603160416051606160716081609161016111612161316141615161616171618161916201621162216231624162516261627162816291630163116321633163416351636163716381639164016411642164316441645164616471648164916501651165216531654165516561657165816591660166116621663166416651666166716681669167016711672167316741675167616771678167916801681168216831684168516861687168816891690169116921693169416951696169716981699170017011702170317041705170617071708170917101711171217131714171517161717171817191720172117221723172417251726172717281729173017311732173317341735173617371738173917401741174217431744174517461747174817491750175117521753175417551756175717581759176017611762176317641765176617671768176917701771177217731774177517761777177817791780178117821783178417851786178717881789179017911792179317941795179617971798179918001801180218031804180518061807180818091810181118121813181418151816181718181819182018211822182318241825182618271828182918301831183218331834183518361837183818391840184118421843184418451846184718481849185018511852185318541855185618571858185918601861186218631864186518661867186818691870187118721873187418751876187718781879188018811882188318841885188618871888188918901891189218931894189518961897189818991900190119021903190419051906190719081909191019111912191319141915191619171918191919201921192219231924192519261927192819291930193119321933193419351936193719381939194019411942194319441945194619471948194919501951195219531954195519561957195819591960196119621963196419651966196719681969197019711972197319741975197619771978197919801981198219831984198519861987198819891990199119921993199419951996199719981999200020012002200320042005200620072008200920102011201220132014201520162017201820192020202120222023202420252026202720282029203020312032203320342035203620372038203920402041204220432044204520462047204820492050205120522053205420552056205720582059206020612062206320642065206620672068206920702071207220732074207520762077207820792080208120822083208420852086208720882089209020912092209320942095209620972098209921002101210221032104210521062107210821092110211121122113211421152116211721182119212021212122212321242125212621272128212921302131213221332134213521362137213821392140214121422143214421452146214721482149215021512152215321542155215621572158215921602161216221632164216521662167216821692170217121722173217421752176217721782179218021812182218321842185218621872188218921902191219221932194219521962197219821992200220122022203220422052206220722082209221022112212221322142215221622172218221922202221222222232224222522262227222822292230223122322233223422352236223722382239224022412242
  1. \input texinfo @c -*-texinfo-*-
  2. @setfilename gprof.info
  3. @c Copyright (C) 1988-2022 Free Software Foundation, Inc.
  4. @settitle GNU gprof
  5. @setchapternewpage odd
  6. @c man begin INCLUDE
  7. @include bfdver.texi
  8. @c man end
  9. @ifnottex
  10. @c This is a dir.info fragment to support semi-automated addition of
  11. @c manuals to an info tree. zoo@cygnus.com is developing this facility.
  12. @dircategory Software development
  13. @direntry
  14. * gprof: (gprof). Profiling your program's execution
  15. @end direntry
  16. @end ifnottex
  17. @copying
  18. This file documents the gprof profiler of the GNU system.
  19. @c man begin COPYRIGHT
  20. Copyright @copyright{} 1988-2022 Free Software Foundation, Inc.
  21. Permission is granted to copy, distribute and/or modify this document
  22. under the terms of the GNU Free Documentation License, Version 1.3
  23. or any later version published by the Free Software Foundation;
  24. with no Invariant Sections, with no Front-Cover Texts, and with no
  25. Back-Cover Texts. A copy of the license is included in the
  26. section entitled ``GNU Free Documentation License''.
  27. @c man end
  28. @end copying
  29. @finalout
  30. @smallbook
  31. @titlepage
  32. @title GNU gprof
  33. @subtitle The @sc{gnu} Profiler
  34. @ifset VERSION_PACKAGE
  35. @subtitle @value{VERSION_PACKAGE}
  36. @end ifset
  37. @subtitle Version @value{VERSION}
  38. @author Jay Fenlason and Richard Stallman
  39. @page
  40. This manual describes the @sc{gnu} profiler, @code{gprof}, and how you
  41. can use it to determine which parts of a program are taking most of the
  42. execution time. We assume that you know how to write, compile, and
  43. execute programs. @sc{gnu} @code{gprof} was written by Jay Fenlason.
  44. Eric S. Raymond made some minor corrections and additions in 2003.
  45. @vskip 0pt plus 1filll
  46. Copyright @copyright{} 1988-2022 Free Software Foundation, Inc.
  47. Permission is granted to copy, distribute and/or modify this document
  48. under the terms of the GNU Free Documentation License, Version 1.3
  49. or any later version published by the Free Software Foundation;
  50. with no Invariant Sections, with no Front-Cover Texts, and with no
  51. Back-Cover Texts. A copy of the license is included in the
  52. section entitled ``GNU Free Documentation License''.
  53. @end titlepage
  54. @contents
  55. @ifnottex
  56. @node Top
  57. @top Profiling a Program: Where Does It Spend Its Time?
  58. This manual describes the @sc{gnu} profiler, @code{gprof}, and how you
  59. can use it to determine which parts of a program are taking most of the
  60. execution time. We assume that you know how to write, compile, and
  61. execute programs. @sc{gnu} @code{gprof} was written by Jay Fenlason.
  62. This manual is for @code{gprof}
  63. @ifset VERSION_PACKAGE
  64. @value{VERSION_PACKAGE}
  65. @end ifset
  66. version @value{VERSION}.
  67. This document is distributed under the terms of the GNU Free
  68. Documentation License version 1.3. A copy of the license is included
  69. in the section entitled ``GNU Free Documentation License''.
  70. @menu
  71. * Introduction:: What profiling means, and why it is useful.
  72. * Compiling:: How to compile your program for profiling.
  73. * Executing:: Executing your program to generate profile data
  74. * Invoking:: How to run @code{gprof}, and its options
  75. * Output:: Interpreting @code{gprof}'s output
  76. * Inaccuracy:: Potential problems you should be aware of
  77. * How do I?:: Answers to common questions
  78. * Incompatibilities:: (between @sc{gnu} @code{gprof} and Unix @code{gprof}.)
  79. * Details:: Details of how profiling is done
  80. * GNU Free Documentation License:: GNU Free Documentation License
  81. @end menu
  82. @end ifnottex
  83. @node Introduction
  84. @chapter Introduction to Profiling
  85. @ifset man
  86. @c man title gprof display call graph profile data
  87. @smallexample
  88. @c man begin SYNOPSIS
  89. gprof [ -[abcDhilLrsTvwxyz] ] [ -[ACeEfFJnNOpPqQRStZ][@var{name}] ]
  90. [ -I @var{dirs} ] [ -d[@var{num}] ] [ -k @var{from/to} ]
  91. [ -m @var{min-count} ] [ -R @var{map_file} ] [ -t @var{table-length} ]
  92. [ --[no-]annotated-source[=@var{name}] ]
  93. [ --[no-]exec-counts[=@var{name}] ]
  94. [ --[no-]flat-profile[=@var{name}] ] [ --[no-]graph[=@var{name}] ]
  95. [ --[no-]time=@var{name}] [ --all-lines ] [ --brief ]
  96. [ --debug[=@var{level}] ] [ --function-ordering ]
  97. [ --file-ordering @var{map_file} ] [ --directory-path=@var{dirs} ]
  98. [ --display-unused-functions ] [ --file-format=@var{name} ]
  99. [ --file-info ] [ --help ] [ --line ] [ --inline-file-names ]
  100. [ --min-count=@var{n} ] [ --no-static ] [ --print-path ]
  101. [ --separate-files ] [ --static-call-graph ] [ --sum ]
  102. [ --table-length=@var{len} ] [ --traditional ] [ --version ]
  103. [ --width=@var{n} ] [ --ignore-non-functions ]
  104. [ --demangle[=@var{STYLE}] ] [ --no-demangle ]
  105. [--external-symbol-table=name]
  106. [ @var{image-file} ] [ @var{profile-file} @dots{} ]
  107. @c man end
  108. @end smallexample
  109. @c man begin DESCRIPTION
  110. @code{gprof} produces an execution profile of C, Pascal, or Fortran77
  111. programs. The effect of called routines is incorporated in the profile
  112. of each caller. The profile data is taken from the call graph profile file
  113. (@file{gmon.out} default) which is created by programs
  114. that are compiled with the @samp{-pg} option of
  115. @code{cc}, @code{pc}, and @code{f77}.
  116. The @samp{-pg} option also links in versions of the library routines
  117. that are compiled for profiling. @code{Gprof} reads the given object
  118. file (the default is @code{a.out}) and establishes the relation between
  119. its symbol table and the call graph profile from @file{gmon.out}.
  120. If more than one profile file is specified, the @code{gprof}
  121. output shows the sum of the profile information in the given profile files.
  122. @code{Gprof} calculates the amount of time spent in each routine.
  123. Next, these times are propagated along the edges of the call graph.
  124. Cycles are discovered, and calls into a cycle are made to share the time
  125. of the cycle.
  126. @c man end
  127. @c man begin BUGS
  128. The granularity of the sampling is shown, but remains
  129. statistical at best.
  130. We assume that the time for each execution of a function
  131. can be expressed by the total time for the function divided
  132. by the number of times the function is called.
  133. Thus the time propagated along the call graph arcs to the function's
  134. parents is directly proportional to the number of times that
  135. arc is traversed.
  136. Parents that are not themselves profiled will have the time of
  137. their profiled children propagated to them, but they will appear
  138. to be spontaneously invoked in the call graph listing, and will
  139. not have their time propagated further.
  140. Similarly, signal catchers, even though profiled, will appear
  141. to be spontaneous (although for more obscure reasons).
  142. Any profiled children of signal catchers should have their times
  143. propagated properly, unless the signal catcher was invoked during
  144. the execution of the profiling routine, in which case all is lost.
  145. The profiled program must call @code{exit}(2)
  146. or return normally for the profiling information to be saved
  147. in the @file{gmon.out} file.
  148. @c man end
  149. @c man begin FILES
  150. @table @code
  151. @item @file{a.out}
  152. the namelist and text space.
  153. @item @file{gmon.out}
  154. dynamic call graph and profile.
  155. @item @file{gmon.sum}
  156. summarized dynamic call graph and profile.
  157. @end table
  158. @c man end
  159. @c man begin SEEALSO
  160. monitor(3), profil(2), cc(1), prof(1), and the Info entry for @file{gprof}.
  161. ``An Execution Profiler for Modular Programs'',
  162. by S. Graham, P. Kessler, M. McKusick;
  163. Software - Practice and Experience,
  164. Vol. 13, pp. 671-685, 1983.
  165. ``gprof: A Call Graph Execution Profiler'',
  166. by S. Graham, P. Kessler, M. McKusick;
  167. Proceedings of the SIGPLAN '82 Symposium on Compiler Construction,
  168. SIGPLAN Notices, Vol. 17, No 6, pp. 120-126, June 1982.
  169. @c man end
  170. @end ifset
  171. Profiling allows you to learn where your program spent its time and which
  172. functions called which other functions while it was executing. This
  173. information can show you which pieces of your program are slower than you
  174. expected, and might be candidates for rewriting to make your program
  175. execute faster. It can also tell you which functions are being called more
  176. or less often than you expected. This may help you spot bugs that had
  177. otherwise been unnoticed.
  178. Since the profiler uses information collected during the actual execution
  179. of your program, it can be used on programs that are too large or too
  180. complex to analyze by reading the source. However, how your program is run
  181. will affect the information that shows up in the profile data. If you
  182. don't use some feature of your program while it is being profiled, no
  183. profile information will be generated for that feature.
  184. Profiling has several steps:
  185. @itemize @bullet
  186. @item
  187. You must compile and link your program with profiling enabled.
  188. @xref{Compiling, ,Compiling a Program for Profiling}.
  189. @item
  190. You must execute your program to generate a profile data file.
  191. @xref{Executing, ,Executing the Program}.
  192. @item
  193. You must run @code{gprof} to analyze the profile data.
  194. @xref{Invoking, ,@code{gprof} Command Summary}.
  195. @end itemize
  196. The next three chapters explain these steps in greater detail.
  197. @c man begin DESCRIPTION
  198. Several forms of output are available from the analysis.
  199. The @dfn{flat profile} shows how much time your program spent in each function,
  200. and how many times that function was called. If you simply want to know
  201. which functions burn most of the cycles, it is stated concisely here.
  202. @xref{Flat Profile, ,The Flat Profile}.
  203. The @dfn{call graph} shows, for each function, which functions called it, which
  204. other functions it called, and how many times. There is also an estimate
  205. of how much time was spent in the subroutines of each function. This can
  206. suggest places where you might try to eliminate function calls that use a
  207. lot of time. @xref{Call Graph, ,The Call Graph}.
  208. The @dfn{annotated source} listing is a copy of the program's
  209. source code, labeled with the number of times each line of the
  210. program was executed. @xref{Annotated Source, ,The Annotated Source
  211. Listing}.
  212. @c man end
  213. To better understand how profiling works, you may wish to read
  214. a description of its implementation.
  215. @xref{Implementation, ,Implementation of Profiling}.
  216. @node Compiling
  217. @chapter Compiling a Program for Profiling
  218. The first step in generating profile information for your program is
  219. to compile and link it with profiling enabled.
  220. To compile a source file for profiling, specify the @samp{-pg} option when
  221. you run the compiler. (This is in addition to the options you normally
  222. use.)
  223. To link the program for profiling, if you use a compiler such as @code{cc}
  224. to do the linking, simply specify @samp{-pg} in addition to your usual
  225. options. The same option, @samp{-pg}, alters either compilation or linking
  226. to do what is necessary for profiling. Here are examples:
  227. @example
  228. cc -g -c myprog.c utils.c -pg
  229. cc -o myprog myprog.o utils.o -pg
  230. @end example
  231. The @samp{-pg} option also works with a command that both compiles and links:
  232. @example
  233. cc -o myprog myprog.c utils.c -g -pg
  234. @end example
  235. Note: The @samp{-pg} option must be part of your compilation options
  236. as well as your link options. If it is not then no call-graph data
  237. will be gathered and when you run @code{gprof} you will get an error
  238. message like this:
  239. @example
  240. gprof: gmon.out file is missing call-graph data
  241. @end example
  242. If you add the @samp{-Q} switch to suppress the printing of the call
  243. graph data you will still be able to see the time samples:
  244. @example
  245. Flat profile:
  246. Each sample counts as 0.01 seconds.
  247. % cumulative self self total
  248. time seconds seconds calls Ts/call Ts/call name
  249. 44.12 0.07 0.07 zazLoop
  250. 35.29 0.14 0.06 main
  251. 20.59 0.17 0.04 bazMillion
  252. @end example
  253. If you run the linker @code{ld} directly instead of through a compiler
  254. such as @code{cc}, you may have to specify a profiling startup file
  255. @file{gcrt0.o} as the first input file instead of the usual startup
  256. file @file{crt0.o}. In addition, you would probably want to
  257. specify the profiling C library, @file{libc_p.a}, by writing
  258. @samp{-lc_p} instead of the usual @samp{-lc}. This is not absolutely
  259. necessary, but doing this gives you number-of-calls information for
  260. standard library functions such as @code{read} and @code{open}. For
  261. example:
  262. @example
  263. ld -o myprog /lib/gcrt0.o myprog.o utils.o -lc_p
  264. @end example
  265. If you are running the program on a system which supports shared
  266. libraries you may run into problems with the profiling support code in
  267. a shared library being called before that library has been fully
  268. initialised. This is usually detected by the program encountering a
  269. segmentation fault as soon as it is run. The solution is to link
  270. against a static version of the library containing the profiling
  271. support code, which for @code{gcc} users can be done via the
  272. @samp{-static} or @samp{-static-libgcc} command-line option. For
  273. example:
  274. @example
  275. gcc -g -pg -static-libgcc myprog.c utils.c -o myprog
  276. @end example
  277. If you compile only some of the modules of the program with @samp{-pg}, you
  278. can still profile the program, but you won't get complete information about
  279. the modules that were compiled without @samp{-pg}. The only information
  280. you get for the functions in those modules is the total time spent in them;
  281. there is no record of how many times they were called, or from where. This
  282. will not affect the flat profile (except that the @code{calls} field for
  283. the functions will be blank), but will greatly reduce the usefulness of the
  284. call graph.
  285. If you wish to perform line-by-line profiling you should use the
  286. @code{gcov} tool instead of @code{gprof}. See that tool's manual or
  287. info pages for more details of how to do this.
  288. Note, older versions of @code{gcc} produce line-by-line profiling
  289. information that works with @code{gprof} rather than @code{gcov} so
  290. there is still support for displaying this kind of information in
  291. @code{gprof}. @xref{Line-by-line, ,Line-by-line Profiling}.
  292. It also worth noting that @code{gcc} implements a
  293. @samp{-finstrument-functions} command-line option which will insert
  294. calls to special user supplied instrumentation routines at the entry
  295. and exit of every function in their program. This can be used to
  296. implement an alternative profiling scheme.
  297. @node Executing
  298. @chapter Executing the Program
  299. Once the program is compiled for profiling, you must run it in order to
  300. generate the information that @code{gprof} needs. Simply run the program
  301. as usual, using the normal arguments, file names, etc. The program should
  302. run normally, producing the same output as usual. It will, however, run
  303. somewhat slower than normal because of the time spent collecting and
  304. writing the profile data.
  305. The way you run the program---the arguments and input that you give
  306. it---may have a dramatic effect on what the profile information shows. The
  307. profile data will describe the parts of the program that were activated for
  308. the particular input you use. For example, if the first command you give
  309. to your program is to quit, the profile data will show the time used in
  310. initialization and in cleanup, but not much else.
  311. Your program will write the profile data into a file called @file{gmon.out}
  312. just before exiting. If there is already a file called @file{gmon.out},
  313. its contents are overwritten. You can rename the file afterwards if you
  314. are concerned that it may be overwritten. If your system libc allows you
  315. may be able to write the profile data under a different name. Set the
  316. GMON_OUT_PREFIX environment variable; this name will be appended with
  317. the PID of the running program.
  318. In order to write the @file{gmon.out} file properly, your program must exit
  319. normally: by returning from @code{main} or by calling @code{exit}. Calling
  320. the low-level function @code{_exit} does not write the profile data, and
  321. neither does abnormal termination due to an unhandled signal.
  322. The @file{gmon.out} file is written in the program's @emph{current working
  323. directory} at the time it exits. This means that if your program calls
  324. @code{chdir}, the @file{gmon.out} file will be left in the last directory
  325. your program @code{chdir}'d to. If you don't have permission to write in
  326. this directory, the file is not written, and you will get an error message.
  327. Older versions of the @sc{gnu} profiling library may also write a file
  328. called @file{bb.out}. This file, if present, contains an human-readable
  329. listing of the basic-block execution counts. Unfortunately, the
  330. appearance of a human-readable @file{bb.out} means the basic-block
  331. counts didn't get written into @file{gmon.out}.
  332. The Perl script @code{bbconv.pl}, included with the @code{gprof}
  333. source distribution, will convert a @file{bb.out} file into
  334. a format readable by @code{gprof}. Invoke it like this:
  335. @smallexample
  336. bbconv.pl < bb.out > @var{bh-data}
  337. @end smallexample
  338. This translates the information in @file{bb.out} into a form that
  339. @code{gprof} can understand. But you still need to tell @code{gprof}
  340. about the existence of this translated information. To do that, include
  341. @var{bb-data} on the @code{gprof} command line, @emph{along with
  342. @file{gmon.out}}, like this:
  343. @smallexample
  344. gprof @var{options} @var{executable-file} gmon.out @var{bb-data} [@var{yet-more-profile-data-files}@dots{}] [> @var{outfile}]
  345. @end smallexample
  346. @node Invoking
  347. @chapter @code{gprof} Command Summary
  348. After you have a profile data file @file{gmon.out}, you can run @code{gprof}
  349. to interpret the information in it. The @code{gprof} program prints a
  350. flat profile and a call graph on standard output. Typically you would
  351. redirect the output of @code{gprof} into a file with @samp{>}.
  352. You run @code{gprof} like this:
  353. @smallexample
  354. gprof @var{options} [@var{executable-file} [@var{profile-data-files}@dots{}]] [> @var{outfile}]
  355. @end smallexample
  356. @noindent
  357. Here square-brackets indicate optional arguments.
  358. If you omit the executable file name, the file @file{a.out} is used. If
  359. you give no profile data file name, the file @file{gmon.out} is used. If
  360. any file is not in the proper format, or if the profile data file does not
  361. appear to belong to the executable file, an error message is printed.
  362. You can give more than one profile data file by entering all their names
  363. after the executable file name; then the statistics in all the data files
  364. are summed together.
  365. The order of these options does not matter.
  366. @menu
  367. * Output Options:: Controlling @code{gprof}'s output style
  368. * Analysis Options:: Controlling how @code{gprof} analyzes its data
  369. * Miscellaneous Options::
  370. * Deprecated Options:: Options you no longer need to use, but which
  371. have been retained for compatibility
  372. * Symspecs:: Specifying functions to include or exclude
  373. @end menu
  374. @node Output Options
  375. @section Output Options
  376. @c man begin OPTIONS
  377. These options specify which of several output formats
  378. @code{gprof} should produce.
  379. Many of these options take an optional @dfn{symspec} to specify
  380. functions to be included or excluded. These options can be
  381. specified multiple times, with different symspecs, to include
  382. or exclude sets of symbols. @xref{Symspecs, ,Symspecs}.
  383. Specifying any of these options overrides the default (@samp{-p -q}),
  384. which prints a flat profile and call graph analysis
  385. for all functions.
  386. @table @code
  387. @item -A[@var{symspec}]
  388. @itemx --annotated-source[=@var{symspec}]
  389. The @samp{-A} option causes @code{gprof} to print annotated source code.
  390. If @var{symspec} is specified, print output only for matching symbols.
  391. @xref{Annotated Source, ,The Annotated Source Listing}.
  392. @item -b
  393. @itemx --brief
  394. If the @samp{-b} option is given, @code{gprof} doesn't print the
  395. verbose blurbs that try to explain the meaning of all of the fields in
  396. the tables. This is useful if you intend to print out the output, or
  397. are tired of seeing the blurbs.
  398. @item -C[@var{symspec}]
  399. @itemx --exec-counts[=@var{symspec}]
  400. The @samp{-C} option causes @code{gprof} to
  401. print a tally of functions and the number of times each was called.
  402. If @var{symspec} is specified, print tally only for matching symbols.
  403. If the profile data file contains basic-block count records, specifying
  404. the @samp{-l} option, along with @samp{-C}, will cause basic-block
  405. execution counts to be tallied and displayed.
  406. @item -i
  407. @itemx --file-info
  408. The @samp{-i} option causes @code{gprof} to display summary information
  409. about the profile data file(s) and then exit. The number of histogram,
  410. call graph, and basic-block count records is displayed.
  411. @item -I @var{dirs}
  412. @itemx --directory-path=@var{dirs}
  413. The @samp{-I} option specifies a list of search directories in
  414. which to find source files. Environment variable @var{GPROF_PATH}
  415. can also be used to convey this information.
  416. Used mostly for annotated source output.
  417. @item -J[@var{symspec}]
  418. @itemx --no-annotated-source[=@var{symspec}]
  419. The @samp{-J} option causes @code{gprof} not to
  420. print annotated source code.
  421. If @var{symspec} is specified, @code{gprof} prints annotated source,
  422. but excludes matching symbols.
  423. @item -L
  424. @itemx --print-path
  425. Normally, source filenames are printed with the path
  426. component suppressed. The @samp{-L} option causes @code{gprof}
  427. to print the full pathname of
  428. source filenames, which is determined
  429. from symbolic debugging information in the image file
  430. and is relative to the directory in which the compiler
  431. was invoked.
  432. @item -p[@var{symspec}]
  433. @itemx --flat-profile[=@var{symspec}]
  434. The @samp{-p} option causes @code{gprof} to print a flat profile.
  435. If @var{symspec} is specified, print flat profile only for matching symbols.
  436. @xref{Flat Profile, ,The Flat Profile}.
  437. @item -P[@var{symspec}]
  438. @itemx --no-flat-profile[=@var{symspec}]
  439. The @samp{-P} option causes @code{gprof} to suppress printing a flat profile.
  440. If @var{symspec} is specified, @code{gprof} prints a flat profile,
  441. but excludes matching symbols.
  442. @item -q[@var{symspec}]
  443. @itemx --graph[=@var{symspec}]
  444. The @samp{-q} option causes @code{gprof} to print the call graph analysis.
  445. If @var{symspec} is specified, print call graph only for matching symbols
  446. and their children.
  447. @xref{Call Graph, ,The Call Graph}.
  448. @item -Q[@var{symspec}]
  449. @itemx --no-graph[=@var{symspec}]
  450. The @samp{-Q} option causes @code{gprof} to suppress printing the
  451. call graph.
  452. If @var{symspec} is specified, @code{gprof} prints a call graph,
  453. but excludes matching symbols.
  454. @item -t
  455. @itemx --table-length=@var{num}
  456. The @samp{-t} option causes the @var{num} most active source lines in
  457. each source file to be listed when source annotation is enabled. The
  458. default is 10.
  459. @item -y
  460. @itemx --separate-files
  461. This option affects annotated source output only.
  462. Normally, @code{gprof} prints annotated source files
  463. to standard-output. If this option is specified,
  464. annotated source for a file named @file{path/@var{filename}}
  465. is generated in the file @file{@var{filename}-ann}. If the underlying
  466. file system would truncate @file{@var{filename}-ann} so that it
  467. overwrites the original @file{@var{filename}}, @code{gprof} generates
  468. annotated source in the file @file{@var{filename}.ann} instead (if the
  469. original file name has an extension, that extension is @emph{replaced}
  470. with @file{.ann}).
  471. @item -Z[@var{symspec}]
  472. @itemx --no-exec-counts[=@var{symspec}]
  473. The @samp{-Z} option causes @code{gprof} not to
  474. print a tally of functions and the number of times each was called.
  475. If @var{symspec} is specified, print tally, but exclude matching symbols.
  476. @item -r
  477. @itemx --function-ordering
  478. The @samp{--function-ordering} option causes @code{gprof} to print a
  479. suggested function ordering for the program based on profiling data.
  480. This option suggests an ordering which may improve paging, tlb and
  481. cache behavior for the program on systems which support arbitrary
  482. ordering of functions in an executable.
  483. The exact details of how to force the linker to place functions
  484. in a particular order is system dependent and out of the scope of this
  485. manual.
  486. @item -R @var{map_file}
  487. @itemx --file-ordering @var{map_file}
  488. The @samp{--file-ordering} option causes @code{gprof} to print a
  489. suggested .o link line ordering for the program based on profiling data.
  490. This option suggests an ordering which may improve paging, tlb and
  491. cache behavior for the program on systems which do not support arbitrary
  492. ordering of functions in an executable.
  493. Use of the @samp{-a} argument is highly recommended with this option.
  494. The @var{map_file} argument is a pathname to a file which provides
  495. function name to object file mappings. The format of the file is similar to
  496. the output of the program @code{nm}.
  497. @smallexample
  498. @group
  499. c-parse.o:00000000 T yyparse
  500. c-parse.o:00000004 C yyerrflag
  501. c-lang.o:00000000 T maybe_objc_method_name
  502. c-lang.o:00000000 T print_lang_statistics
  503. c-lang.o:00000000 T recognize_objc_keyword
  504. c-decl.o:00000000 T print_lang_identifier
  505. c-decl.o:00000000 T print_lang_type
  506. @dots{}
  507. @end group
  508. @end smallexample
  509. To create a @var{map_file} with @sc{gnu} @code{nm}, type a command like
  510. @kbd{nm --extern-only --defined-only -v --print-file-name program-name}.
  511. @item -T
  512. @itemx --traditional
  513. The @samp{-T} option causes @code{gprof} to print its output in
  514. ``traditional'' BSD style.
  515. @item -w @var{width}
  516. @itemx --width=@var{width}
  517. Sets width of output lines to @var{width}.
  518. Currently only used when printing the function index at the bottom
  519. of the call graph.
  520. @item -x
  521. @itemx --all-lines
  522. This option affects annotated source output only.
  523. By default, only the lines at the beginning of a basic-block
  524. are annotated. If this option is specified, every line in
  525. a basic-block is annotated by repeating the annotation for the
  526. first line. This behavior is similar to @code{tcov}'s @samp{-a}.
  527. @item --demangle[=@var{style}]
  528. @itemx --no-demangle
  529. These options control whether C++ symbol names should be demangled when
  530. printing output. The default is to demangle symbols. The
  531. @code{--no-demangle} option may be used to turn off demangling. Different
  532. compilers have different mangling styles. The optional demangling style
  533. argument can be used to choose an appropriate demangling style for your
  534. compiler.
  535. @end table
  536. @node Analysis Options
  537. @section Analysis Options
  538. @table @code
  539. @item -a
  540. @itemx --no-static
  541. The @samp{-a} option causes @code{gprof} to suppress the printing of
  542. statically declared (private) functions. (These are functions whose
  543. names are not listed as global, and which are not visible outside the
  544. file/function/block where they were defined.) Time spent in these
  545. functions, calls to/from them, etc., will all be attributed to the
  546. function that was loaded directly before it in the executable file.
  547. @c This is compatible with Unix @code{gprof}, but a bad idea.
  548. This option affects both the flat profile and the call graph.
  549. @item -c
  550. @itemx --static-call-graph
  551. The @samp{-c} option causes the call graph of the program to be
  552. augmented by a heuristic which examines the text space of the object
  553. file and identifies function calls in the binary machine code.
  554. Since normal call graph records are only generated when functions are
  555. entered, this option identifies children that could have been called,
  556. but never were. Calls to functions that were not compiled with
  557. profiling enabled are also identified, but only if symbol table
  558. entries are present for them.
  559. Calls to dynamic library routines are typically @emph{not} found
  560. by this option.
  561. Parents or children identified via this heuristic
  562. are indicated in the call graph with call counts of @samp{0}.
  563. @item -D
  564. @itemx --ignore-non-functions
  565. The @samp{-D} option causes @code{gprof} to ignore symbols which
  566. are not known to be functions. This option will give more accurate
  567. profile data on systems where it is supported (Solaris and HPUX for
  568. example).
  569. @item -k @var{from}/@var{to}
  570. The @samp{-k} option allows you to delete from the call graph any arcs from
  571. symbols matching symspec @var{from} to those matching symspec @var{to}.
  572. @item -l
  573. @itemx --line
  574. The @samp{-l} option enables line-by-line profiling, which causes
  575. histogram hits to be charged to individual source code lines,
  576. instead of functions. This feature only works with programs compiled
  577. by older versions of the @code{gcc} compiler. Newer versions of
  578. @code{gcc} are designed to work with the @code{gcov} tool instead.
  579. If the program was compiled with basic-block counting enabled,
  580. this option will also identify how many times each line of
  581. code was executed.
  582. While line-by-line profiling can help isolate where in a large function
  583. a program is spending its time, it also significantly increases
  584. the running time of @code{gprof}, and magnifies statistical
  585. inaccuracies.
  586. @xref{Sampling Error, ,Statistical Sampling Error}.
  587. @item --inline-file-names
  588. This option causes @code{gprof} to print the source file after each
  589. symbol in both the flat profile and the call graph. The full path to the
  590. file is printed if used with the @samp{-L} option.
  591. @item -m @var{num}
  592. @itemx --min-count=@var{num}
  593. This option affects execution count output only.
  594. Symbols that are executed less than @var{num} times are suppressed.
  595. @item -n@var{symspec}
  596. @itemx --time=@var{symspec}
  597. The @samp{-n} option causes @code{gprof}, in its call graph analysis,
  598. to only propagate times for symbols matching @var{symspec}.
  599. @item -N@var{symspec}
  600. @itemx --no-time=@var{symspec}
  601. The @samp{-n} option causes @code{gprof}, in its call graph analysis,
  602. not to propagate times for symbols matching @var{symspec}.
  603. @item -S@var{filename}
  604. @itemx --external-symbol-table=@var{filename}
  605. The @samp{-S} option causes @code{gprof} to read an external symbol table
  606. file, such as @file{/proc/kallsyms}, rather than read the symbol table
  607. from the given object file (the default is @code{a.out}). This is useful
  608. for profiling kernel modules.
  609. @item -z
  610. @itemx --display-unused-functions
  611. If you give the @samp{-z} option, @code{gprof} will mention all
  612. functions in the flat profile, even those that were never called, and
  613. that had no time spent in them. This is useful in conjunction with the
  614. @samp{-c} option for discovering which routines were never called.
  615. @end table
  616. @node Miscellaneous Options
  617. @section Miscellaneous Options
  618. @table @code
  619. @item -d[@var{num}]
  620. @itemx --debug[=@var{num}]
  621. The @samp{-d @var{num}} option specifies debugging options.
  622. If @var{num} is not specified, enable all debugging.
  623. @xref{Debugging, ,Debugging @code{gprof}}.
  624. @item -h
  625. @itemx --help
  626. The @samp{-h} option prints command line usage.
  627. @item -O@var{name}
  628. @itemx --file-format=@var{name}
  629. Selects the format of the profile data files. Recognized formats are
  630. @samp{auto} (the default), @samp{bsd}, @samp{4.4bsd}, @samp{magic}, and
  631. @samp{prof} (not yet supported).
  632. @item -s
  633. @itemx --sum
  634. The @samp{-s} option causes @code{gprof} to summarize the information
  635. in the profile data files it read in, and write out a profile data
  636. file called @file{gmon.sum}, which contains all the information from
  637. the profile data files that @code{gprof} read in. The file @file{gmon.sum}
  638. may be one of the specified input files; the effect of this is to
  639. merge the data in the other input files into @file{gmon.sum}.
  640. Eventually you can run @code{gprof} again without @samp{-s} to analyze the
  641. cumulative data in the file @file{gmon.sum}.
  642. @item -v
  643. @itemx --version
  644. The @samp{-v} flag causes @code{gprof} to print the current version
  645. number, and then exit.
  646. @end table
  647. @node Deprecated Options
  648. @section Deprecated Options
  649. These options have been replaced with newer versions that use symspecs.
  650. @table @code
  651. @item -e @var{function_name}
  652. The @samp{-e @var{function}} option tells @code{gprof} to not print
  653. information about the function @var{function_name} (and its
  654. children@dots{}) in the call graph. The function will still be listed
  655. as a child of any functions that call it, but its index number will be
  656. shown as @samp{[not printed]}. More than one @samp{-e} option may be
  657. given; only one @var{function_name} may be indicated with each @samp{-e}
  658. option.
  659. @item -E @var{function_name}
  660. The @code{-E @var{function}} option works like the @code{-e} option, but
  661. time spent in the function (and children who were not called from
  662. anywhere else), will not be used to compute the percentages-of-time for
  663. the call graph. More than one @samp{-E} option may be given; only one
  664. @var{function_name} may be indicated with each @samp{-E} option.
  665. @item -f @var{function_name}
  666. The @samp{-f @var{function}} option causes @code{gprof} to limit the
  667. call graph to the function @var{function_name} and its children (and
  668. their children@dots{}). More than one @samp{-f} option may be given;
  669. only one @var{function_name} may be indicated with each @samp{-f}
  670. option.
  671. @item -F @var{function_name}
  672. The @samp{-F @var{function}} option works like the @code{-f} option, but
  673. only time spent in the function and its children (and their
  674. children@dots{}) will be used to determine total-time and
  675. percentages-of-time for the call graph. More than one @samp{-F} option
  676. may be given; only one @var{function_name} may be indicated with each
  677. @samp{-F} option. The @samp{-F} option overrides the @samp{-E} option.
  678. @end table
  679. @c man end
  680. Note that only one function can be specified with each @code{-e},
  681. @code{-E}, @code{-f} or @code{-F} option. To specify more than one
  682. function, use multiple options. For example, this command:
  683. @example
  684. gprof -e boring -f foo -f bar myprogram > gprof.output
  685. @end example
  686. @noindent
  687. lists in the call graph all functions that were reached from either
  688. @code{foo} or @code{bar} and were not reachable from @code{boring}.
  689. @node Symspecs
  690. @section Symspecs
  691. Many of the output options allow functions to be included or excluded
  692. using @dfn{symspecs} (symbol specifications), which observe the
  693. following syntax:
  694. @example
  695. filename_containing_a_dot
  696. | funcname_not_containing_a_dot
  697. | linenumber
  698. | ( [ any_filename ] `:' ( any_funcname | linenumber ) )
  699. @end example
  700. Here are some sample symspecs:
  701. @table @samp
  702. @item main.c
  703. Selects everything in file @file{main.c}---the
  704. dot in the string tells @code{gprof} to interpret
  705. the string as a filename, rather than as
  706. a function name. To select a file whose
  707. name does not contain a dot, a trailing colon
  708. should be specified. For example, @samp{odd:} is
  709. interpreted as the file named @file{odd}.
  710. @item main
  711. Selects all functions named @samp{main}.
  712. Note that there may be multiple instances of the same function name
  713. because some of the definitions may be local (i.e., static). Unless a
  714. function name is unique in a program, you must use the colon notation
  715. explained below to specify a function from a specific source file.
  716. Sometimes, function names contain dots. In such cases, it is necessary
  717. to add a leading colon to the name. For example, @samp{:.mul} selects
  718. function @samp{.mul}.
  719. In some object file formats, symbols have a leading underscore.
  720. @code{gprof} will normally not print these underscores. When you name a
  721. symbol in a symspec, you should type it exactly as @code{gprof} prints
  722. it in its output. For example, if the compiler produces a symbol
  723. @samp{_main} from your @code{main} function, @code{gprof} still prints
  724. it as @samp{main} in its output, so you should use @samp{main} in
  725. symspecs.
  726. @item main.c:main
  727. Selects function @samp{main} in file @file{main.c}.
  728. @item main.c:134
  729. Selects line 134 in file @file{main.c}.
  730. @end table
  731. @node Output
  732. @chapter Interpreting @code{gprof}'s Output
  733. @code{gprof} can produce several different output styles, the
  734. most important of which are described below. The simplest output
  735. styles (file information, execution count, and function and file ordering)
  736. are not described here, but are documented with the respective options
  737. that trigger them.
  738. @xref{Output Options, ,Output Options}.
  739. @menu
  740. * Flat Profile:: The flat profile shows how much time was spent
  741. executing directly in each function.
  742. * Call Graph:: The call graph shows which functions called which
  743. others, and how much time each function used
  744. when its subroutine calls are included.
  745. * Line-by-line:: @code{gprof} can analyze individual source code lines
  746. * Annotated Source:: The annotated source listing displays source code
  747. labeled with execution counts
  748. @end menu
  749. @node Flat Profile
  750. @section The Flat Profile
  751. @cindex flat profile
  752. The @dfn{flat profile} shows the total amount of time your program
  753. spent executing each function. Unless the @samp{-z} option is given,
  754. functions with no apparent time spent in them, and no apparent calls
  755. to them, are not mentioned. Note that if a function was not compiled
  756. for profiling, and didn't run long enough to show up on the program
  757. counter histogram, it will be indistinguishable from a function that
  758. was never called.
  759. This is part of a flat profile for a small program:
  760. @smallexample
  761. @group
  762. Flat profile:
  763. Each sample counts as 0.01 seconds.
  764. % cumulative self self total
  765. time seconds seconds calls ms/call ms/call name
  766. 33.34 0.02 0.02 7208 0.00 0.00 open
  767. 16.67 0.03 0.01 244 0.04 0.12 offtime
  768. 16.67 0.04 0.01 8 1.25 1.25 memccpy
  769. 16.67 0.05 0.01 7 1.43 1.43 write
  770. 16.67 0.06 0.01 mcount
  771. 0.00 0.06 0.00 236 0.00 0.00 tzset
  772. 0.00 0.06 0.00 192 0.00 0.00 tolower
  773. 0.00 0.06 0.00 47 0.00 0.00 strlen
  774. 0.00 0.06 0.00 45 0.00 0.00 strchr
  775. 0.00 0.06 0.00 1 0.00 50.00 main
  776. 0.00 0.06 0.00 1 0.00 0.00 memcpy
  777. 0.00 0.06 0.00 1 0.00 10.11 print
  778. 0.00 0.06 0.00 1 0.00 0.00 profil
  779. 0.00 0.06 0.00 1 0.00 50.00 report
  780. @dots{}
  781. @end group
  782. @end smallexample
  783. @noindent
  784. The functions are sorted first by decreasing run-time spent in them,
  785. then by decreasing number of calls, then alphabetically by name. The
  786. functions @samp{mcount} and @samp{profil} are part of the profiling
  787. apparatus and appear in every flat profile; their time gives a measure of
  788. the amount of overhead due to profiling.
  789. Just before the column headers, a statement appears indicating
  790. how much time each sample counted as.
  791. This @dfn{sampling period} estimates the margin of error in each of the time
  792. figures. A time figure that is not much larger than this is not
  793. reliable. In this example, each sample counted as 0.01 seconds,
  794. suggesting a 100 Hz sampling rate.
  795. The program's total execution time was 0.06
  796. seconds, as indicated by the @samp{cumulative seconds} field. Since
  797. each sample counted for 0.01 seconds, this means only six samples
  798. were taken during the run. Two of the samples occurred while the
  799. program was in the @samp{open} function, as indicated by the
  800. @samp{self seconds} field. Each of the other four samples
  801. occurred one each in @samp{offtime}, @samp{memccpy}, @samp{write},
  802. and @samp{mcount}.
  803. Since only six samples were taken, none of these values can
  804. be regarded as particularly reliable.
  805. In another run,
  806. the @samp{self seconds} field for
  807. @samp{mcount} might well be @samp{0.00} or @samp{0.02}.
  808. @xref{Sampling Error, ,Statistical Sampling Error},
  809. for a complete discussion.
  810. The remaining functions in the listing (those whose
  811. @samp{self seconds} field is @samp{0.00}) didn't appear
  812. in the histogram samples at all. However, the call graph
  813. indicated that they were called, so therefore they are listed,
  814. sorted in decreasing order by the @samp{calls} field.
  815. Clearly some time was spent executing these functions,
  816. but the paucity of histogram samples prevents any
  817. determination of how much time each took.
  818. Here is what the fields in each line mean:
  819. @table @code
  820. @item % time
  821. This is the percentage of the total execution time your program spent
  822. in this function. These should all add up to 100%.
  823. @item cumulative seconds
  824. This is the cumulative total number of seconds the computer spent
  825. executing this functions, plus the time spent in all the functions
  826. above this one in this table.
  827. @item self seconds
  828. This is the number of seconds accounted for by this function alone.
  829. The flat profile listing is sorted first by this number.
  830. @item calls
  831. This is the total number of times the function was called. If the
  832. function was never called, or the number of times it was called cannot
  833. be determined (probably because the function was not compiled with
  834. profiling enabled), the @dfn{calls} field is blank.
  835. @item self ms/call
  836. This represents the average number of milliseconds spent in this
  837. function per call, if this function is profiled. Otherwise, this field
  838. is blank for this function.
  839. @item total ms/call
  840. This represents the average number of milliseconds spent in this
  841. function and its descendants per call, if this function is profiled.
  842. Otherwise, this field is blank for this function.
  843. This is the only field in the flat profile that uses call graph analysis.
  844. @item name
  845. This is the name of the function. The flat profile is sorted by this
  846. field alphabetically after the @dfn{self seconds} and @dfn{calls}
  847. fields are sorted.
  848. @end table
  849. @node Call Graph
  850. @section The Call Graph
  851. @cindex call graph
  852. The @dfn{call graph} shows how much time was spent in each function
  853. and its children. From this information, you can find functions that,
  854. while they themselves may not have used much time, called other
  855. functions that did use unusual amounts of time.
  856. Here is a sample call from a small program. This call came from the
  857. same @code{gprof} run as the flat profile example in the previous
  858. section.
  859. @smallexample
  860. @group
  861. granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds
  862. index % time self children called name
  863. <spontaneous>
  864. [1] 100.0 0.00 0.05 start [1]
  865. 0.00 0.05 1/1 main [2]
  866. 0.00 0.00 1/2 on_exit [28]
  867. 0.00 0.00 1/1 exit [59]
  868. -----------------------------------------------
  869. 0.00 0.05 1/1 start [1]
  870. [2] 100.0 0.00 0.05 1 main [2]
  871. 0.00 0.05 1/1 report [3]
  872. -----------------------------------------------
  873. 0.00 0.05 1/1 main [2]
  874. [3] 100.0 0.00 0.05 1 report [3]
  875. 0.00 0.03 8/8 timelocal [6]
  876. 0.00 0.01 1/1 print [9]
  877. 0.00 0.01 9/9 fgets [12]
  878. 0.00 0.00 12/34 strncmp <cycle 1> [40]
  879. 0.00 0.00 8/8 lookup [20]
  880. 0.00 0.00 1/1 fopen [21]
  881. 0.00 0.00 8/8 chewtime [24]
  882. 0.00 0.00 8/16 skipspace [44]
  883. -----------------------------------------------
  884. [4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
  885. 0.01 0.02 244+260 offtime <cycle 2> [7]
  886. 0.00 0.00 236+1 tzset <cycle 2> [26]
  887. -----------------------------------------------
  888. @end group
  889. @end smallexample
  890. The lines full of dashes divide this table into @dfn{entries}, one for each
  891. function. Each entry has one or more lines.
  892. In each entry, the primary line is the one that starts with an index number
  893. in square brackets. The end of this line says which function the entry is
  894. for. The preceding lines in the entry describe the callers of this
  895. function and the following lines describe its subroutines (also called
  896. @dfn{children} when we speak of the call graph).
  897. The entries are sorted by time spent in the function and its subroutines.
  898. The internal profiling function @code{mcount} (@pxref{Flat Profile, ,The
  899. Flat Profile}) is never mentioned in the call graph.
  900. @menu
  901. * Primary:: Details of the primary line's contents.
  902. * Callers:: Details of caller-lines' contents.
  903. * Subroutines:: Details of subroutine-lines' contents.
  904. * Cycles:: When there are cycles of recursion,
  905. such as @code{a} calls @code{b} calls @code{a}@dots{}
  906. @end menu
  907. @node Primary
  908. @subsection The Primary Line
  909. The @dfn{primary line} in a call graph entry is the line that
  910. describes the function which the entry is about and gives the overall
  911. statistics for this function.
  912. For reference, we repeat the primary line from the entry for function
  913. @code{report} in our main example, together with the heading line that
  914. shows the names of the fields:
  915. @smallexample
  916. @group
  917. index % time self children called name
  918. @dots{}
  919. [3] 100.0 0.00 0.05 1 report [3]
  920. @end group
  921. @end smallexample
  922. Here is what the fields in the primary line mean:
  923. @table @code
  924. @item index
  925. Entries are numbered with consecutive integers. Each function
  926. therefore has an index number, which appears at the beginning of its
  927. primary line.
  928. Each cross-reference to a function, as a caller or subroutine of
  929. another, gives its index number as well as its name. The index number
  930. guides you if you wish to look for the entry for that function.
  931. @item % time
  932. This is the percentage of the total time that was spent in this
  933. function, including time spent in subroutines called from this
  934. function.
  935. The time spent in this function is counted again for the callers of
  936. this function. Therefore, adding up these percentages is meaningless.
  937. @item self
  938. This is the total amount of time spent in this function. This
  939. should be identical to the number printed in the @code{seconds} field
  940. for this function in the flat profile.
  941. @item children
  942. This is the total amount of time spent in the subroutine calls made by
  943. this function. This should be equal to the sum of all the @code{self}
  944. and @code{children} entries of the children listed directly below this
  945. function.
  946. @item called
  947. This is the number of times the function was called.
  948. If the function called itself recursively, there are two numbers,
  949. separated by a @samp{+}. The first number counts non-recursive calls,
  950. and the second counts recursive calls.
  951. In the example above, the function @code{report} was called once from
  952. @code{main}.
  953. @item name
  954. This is the name of the current function. The index number is
  955. repeated after it.
  956. If the function is part of a cycle of recursion, the cycle number is
  957. printed between the function's name and the index number
  958. (@pxref{Cycles, ,How Mutually Recursive Functions Are Described}).
  959. For example, if function @code{gnurr} is part of
  960. cycle number one, and has index number twelve, its primary line would
  961. be end like this:
  962. @example
  963. gnurr <cycle 1> [12]
  964. @end example
  965. @end table
  966. @node Callers
  967. @subsection Lines for a Function's Callers
  968. A function's entry has a line for each function it was called by.
  969. These lines' fields correspond to the fields of the primary line, but
  970. their meanings are different because of the difference in context.
  971. For reference, we repeat two lines from the entry for the function
  972. @code{report}, the primary line and one caller-line preceding it, together
  973. with the heading line that shows the names of the fields:
  974. @smallexample
  975. index % time self children called name
  976. @dots{}
  977. 0.00 0.05 1/1 main [2]
  978. [3] 100.0 0.00 0.05 1 report [3]
  979. @end smallexample
  980. Here are the meanings of the fields in the caller-line for @code{report}
  981. called from @code{main}:
  982. @table @code
  983. @item self
  984. An estimate of the amount of time spent in @code{report} itself when it was
  985. called from @code{main}.
  986. @item children
  987. An estimate of the amount of time spent in subroutines of @code{report}
  988. when @code{report} was called from @code{main}.
  989. The sum of the @code{self} and @code{children} fields is an estimate
  990. of the amount of time spent within calls to @code{report} from @code{main}.
  991. @item called
  992. Two numbers: the number of times @code{report} was called from @code{main},
  993. followed by the total number of non-recursive calls to @code{report} from
  994. all its callers.
  995. @item name and index number
  996. The name of the caller of @code{report} to which this line applies,
  997. followed by the caller's index number.
  998. Not all functions have entries in the call graph; some
  999. options to @code{gprof} request the omission of certain functions.
  1000. When a caller has no entry of its own, it still has caller-lines
  1001. in the entries of the functions it calls.
  1002. If the caller is part of a recursion cycle, the cycle number is
  1003. printed between the name and the index number.
  1004. @end table
  1005. If the identity of the callers of a function cannot be determined, a
  1006. dummy caller-line is printed which has @samp{<spontaneous>} as the
  1007. ``caller's name'' and all other fields blank. This can happen for
  1008. signal handlers.
  1009. @c What if some calls have determinable callers' names but not all?
  1010. @c FIXME - still relevant?
  1011. @node Subroutines
  1012. @subsection Lines for a Function's Subroutines
  1013. A function's entry has a line for each of its subroutines---in other
  1014. words, a line for each other function that it called. These lines'
  1015. fields correspond to the fields of the primary line, but their meanings
  1016. are different because of the difference in context.
  1017. For reference, we repeat two lines from the entry for the function
  1018. @code{main}, the primary line and a line for a subroutine, together
  1019. with the heading line that shows the names of the fields:
  1020. @smallexample
  1021. index % time self children called name
  1022. @dots{}
  1023. [2] 100.0 0.00 0.05 1 main [2]
  1024. 0.00 0.05 1/1 report [3]
  1025. @end smallexample
  1026. Here are the meanings of the fields in the subroutine-line for @code{main}
  1027. calling @code{report}:
  1028. @table @code
  1029. @item self
  1030. An estimate of the amount of time spent directly within @code{report}
  1031. when @code{report} was called from @code{main}.
  1032. @item children
  1033. An estimate of the amount of time spent in subroutines of @code{report}
  1034. when @code{report} was called from @code{main}.
  1035. The sum of the @code{self} and @code{children} fields is an estimate
  1036. of the total time spent in calls to @code{report} from @code{main}.
  1037. @item called
  1038. Two numbers, the number of calls to @code{report} from @code{main}
  1039. followed by the total number of non-recursive calls to @code{report}.
  1040. This ratio is used to determine how much of @code{report}'s @code{self}
  1041. and @code{children} time gets credited to @code{main}.
  1042. @xref{Assumptions, ,Estimating @code{children} Times}.
  1043. @item name
  1044. The name of the subroutine of @code{main} to which this line applies,
  1045. followed by the subroutine's index number.
  1046. If the caller is part of a recursion cycle, the cycle number is
  1047. printed between the name and the index number.
  1048. @end table
  1049. @node Cycles
  1050. @subsection How Mutually Recursive Functions Are Described
  1051. @cindex cycle
  1052. @cindex recursion cycle
  1053. The graph may be complicated by the presence of @dfn{cycles of
  1054. recursion} in the call graph. A cycle exists if a function calls
  1055. another function that (directly or indirectly) calls (or appears to
  1056. call) the original function. For example: if @code{a} calls @code{b},
  1057. and @code{b} calls @code{a}, then @code{a} and @code{b} form a cycle.
  1058. Whenever there are call paths both ways between a pair of functions, they
  1059. belong to the same cycle. If @code{a} and @code{b} call each other and
  1060. @code{b} and @code{c} call each other, all three make one cycle. Note that
  1061. even if @code{b} only calls @code{a} if it was not called from @code{a},
  1062. @code{gprof} cannot determine this, so @code{a} and @code{b} are still
  1063. considered a cycle.
  1064. The cycles are numbered with consecutive integers. When a function
  1065. belongs to a cycle, each time the function name appears in the call graph
  1066. it is followed by @samp{<cycle @var{number}>}.
  1067. The reason cycles matter is that they make the time values in the call
  1068. graph paradoxical. The ``time spent in children'' of @code{a} should
  1069. include the time spent in its subroutine @code{b} and in @code{b}'s
  1070. subroutines---but one of @code{b}'s subroutines is @code{a}! How much of
  1071. @code{a}'s time should be included in the children of @code{a}, when
  1072. @code{a} is indirectly recursive?
  1073. The way @code{gprof} resolves this paradox is by creating a single entry
  1074. for the cycle as a whole. The primary line of this entry describes the
  1075. total time spent directly in the functions of the cycle. The
  1076. ``subroutines'' of the cycle are the individual functions of the cycle, and
  1077. all other functions that were called directly by them. The ``callers'' of
  1078. the cycle are the functions, outside the cycle, that called functions in
  1079. the cycle.
  1080. Here is an example portion of a call graph which shows a cycle containing
  1081. functions @code{a} and @code{b}. The cycle was entered by a call to
  1082. @code{a} from @code{main}; both @code{a} and @code{b} called @code{c}.
  1083. @smallexample
  1084. index % time self children called name
  1085. ----------------------------------------
  1086. 1.77 0 1/1 main [2]
  1087. [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
  1088. 1.02 0 3 b <cycle 1> [4]
  1089. 0.75 0 2 a <cycle 1> [5]
  1090. ----------------------------------------
  1091. 3 a <cycle 1> [5]
  1092. [4] 52.85 1.02 0 0 b <cycle 1> [4]
  1093. 2 a <cycle 1> [5]
  1094. 0 0 3/6 c [6]
  1095. ----------------------------------------
  1096. 1.77 0 1/1 main [2]
  1097. 2 b <cycle 1> [4]
  1098. [5] 38.86 0.75 0 1 a <cycle 1> [5]
  1099. 3 b <cycle 1> [4]
  1100. 0 0 3/6 c [6]
  1101. ----------------------------------------
  1102. @end smallexample
  1103. @noindent
  1104. (The entire call graph for this program contains in addition an entry for
  1105. @code{main}, which calls @code{a}, and an entry for @code{c}, with callers
  1106. @code{a} and @code{b}.)
  1107. @smallexample
  1108. index % time self children called name
  1109. <spontaneous>
  1110. [1] 100.00 0 1.93 0 start [1]
  1111. 0.16 1.77 1/1 main [2]
  1112. ----------------------------------------
  1113. 0.16 1.77 1/1 start [1]
  1114. [2] 100.00 0.16 1.77 1 main [2]
  1115. 1.77 0 1/1 a <cycle 1> [5]
  1116. ----------------------------------------
  1117. 1.77 0 1/1 main [2]
  1118. [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
  1119. 1.02 0 3 b <cycle 1> [4]
  1120. 0.75 0 2 a <cycle 1> [5]
  1121. 0 0 6/6 c [6]
  1122. ----------------------------------------
  1123. 3 a <cycle 1> [5]
  1124. [4] 52.85 1.02 0 0 b <cycle 1> [4]
  1125. 2 a <cycle 1> [5]
  1126. 0 0 3/6 c [6]
  1127. ----------------------------------------
  1128. 1.77 0 1/1 main [2]
  1129. 2 b <cycle 1> [4]
  1130. [5] 38.86 0.75 0 1 a <cycle 1> [5]
  1131. 3 b <cycle 1> [4]
  1132. 0 0 3/6 c [6]
  1133. ----------------------------------------
  1134. 0 0 3/6 b <cycle 1> [4]
  1135. 0 0 3/6 a <cycle 1> [5]
  1136. [6] 0.00 0 0 6 c [6]
  1137. ----------------------------------------
  1138. @end smallexample
  1139. The @code{self} field of the cycle's primary line is the total time
  1140. spent in all the functions of the cycle. It equals the sum of the
  1141. @code{self} fields for the individual functions in the cycle, found
  1142. in the entry in the subroutine lines for these functions.
  1143. The @code{children} fields of the cycle's primary line and subroutine lines
  1144. count only subroutines outside the cycle. Even though @code{a} calls
  1145. @code{b}, the time spent in those calls to @code{b} is not counted in
  1146. @code{a}'s @code{children} time. Thus, we do not encounter the problem of
  1147. what to do when the time in those calls to @code{b} includes indirect
  1148. recursive calls back to @code{a}.
  1149. The @code{children} field of a caller-line in the cycle's entry estimates
  1150. the amount of time spent @emph{in the whole cycle}, and its other
  1151. subroutines, on the times when that caller called a function in the cycle.
  1152. The @code{called} field in the primary line for the cycle has two numbers:
  1153. first, the number of times functions in the cycle were called by functions
  1154. outside the cycle; second, the number of times they were called by
  1155. functions in the cycle (including times when a function in the cycle calls
  1156. itself). This is a generalization of the usual split into non-recursive and
  1157. recursive calls.
  1158. The @code{called} field of a subroutine-line for a cycle member in the
  1159. cycle's entry says how many time that function was called from functions in
  1160. the cycle. The total of all these is the second number in the primary line's
  1161. @code{called} field.
  1162. In the individual entry for a function in a cycle, the other functions in
  1163. the same cycle can appear as subroutines and as callers. These lines show
  1164. how many times each function in the cycle called or was called from each other
  1165. function in the cycle. The @code{self} and @code{children} fields in these
  1166. lines are blank because of the difficulty of defining meanings for them
  1167. when recursion is going on.
  1168. @node Line-by-line
  1169. @section Line-by-line Profiling
  1170. @code{gprof}'s @samp{-l} option causes the program to perform
  1171. @dfn{line-by-line} profiling. In this mode, histogram
  1172. samples are assigned not to functions, but to individual
  1173. lines of source code. This only works with programs compiled with
  1174. older versions of the @code{gcc} compiler. Newer versions of @code{gcc}
  1175. use a different program - @code{gcov} - to display line-by-line
  1176. profiling information.
  1177. With the older versions of @code{gcc} the program usually has to be
  1178. compiled with a @samp{-g} option, in addition to @samp{-pg}, in order
  1179. to generate debugging symbols for tracking source code lines.
  1180. Note, in much older versions of @code{gcc} the program had to be
  1181. compiled with the @samp{-a} command-line option as well.
  1182. The flat profile is the most useful output table
  1183. in line-by-line mode.
  1184. The call graph isn't as useful as normal, since
  1185. the current version of @code{gprof} does not propagate
  1186. call graph arcs from source code lines to the enclosing function.
  1187. The call graph does, however, show each line of code
  1188. that called each function, along with a count.
  1189. Here is a section of @code{gprof}'s output, without line-by-line profiling.
  1190. Note that @code{ct_init} accounted for four histogram hits, and
  1191. 13327 calls to @code{init_block}.
  1192. @smallexample
  1193. Flat profile:
  1194. Each sample counts as 0.01 seconds.
  1195. % cumulative self self total
  1196. time seconds seconds calls us/call us/call name
  1197. 30.77 0.13 0.04 6335 6.31 6.31 ct_init
  1198. Call graph (explanation follows)
  1199. granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
  1200. index % time self children called name
  1201. 0.00 0.00 1/13496 name_too_long
  1202. 0.00 0.00 40/13496 deflate
  1203. 0.00 0.00 128/13496 deflate_fast
  1204. 0.00 0.00 13327/13496 ct_init
  1205. [7] 0.0 0.00 0.00 13496 init_block
  1206. @end smallexample
  1207. Now let's look at some of @code{gprof}'s output from the same program run,
  1208. this time with line-by-line profiling enabled. Note that @code{ct_init}'s
  1209. four histogram hits are broken down into four lines of source code---one hit
  1210. occurred on each of lines 349, 351, 382 and 385. In the call graph,
  1211. note how
  1212. @code{ct_init}'s 13327 calls to @code{init_block} are broken down
  1213. into one call from line 396, 3071 calls from line 384, 3730 calls
  1214. from line 385, and 6525 calls from 387.
  1215. @smallexample
  1216. Flat profile:
  1217. Each sample counts as 0.01 seconds.
  1218. % cumulative self
  1219. time seconds seconds calls name
  1220. 7.69 0.10 0.01 ct_init (trees.c:349)
  1221. 7.69 0.11 0.01 ct_init (trees.c:351)
  1222. 7.69 0.12 0.01 ct_init (trees.c:382)
  1223. 7.69 0.13 0.01 ct_init (trees.c:385)
  1224. Call graph (explanation follows)
  1225. granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
  1226. % time self children called name
  1227. 0.00 0.00 1/13496 name_too_long (gzip.c:1440)
  1228. 0.00 0.00 1/13496 deflate (deflate.c:763)
  1229. 0.00 0.00 1/13496 ct_init (trees.c:396)
  1230. 0.00 0.00 2/13496 deflate (deflate.c:727)
  1231. 0.00 0.00 4/13496 deflate (deflate.c:686)
  1232. 0.00 0.00 5/13496 deflate (deflate.c:675)
  1233. 0.00 0.00 12/13496 deflate (deflate.c:679)
  1234. 0.00 0.00 16/13496 deflate (deflate.c:730)
  1235. 0.00 0.00 128/13496 deflate_fast (deflate.c:654)
  1236. 0.00 0.00 3071/13496 ct_init (trees.c:384)
  1237. 0.00 0.00 3730/13496 ct_init (trees.c:385)
  1238. 0.00 0.00 6525/13496 ct_init (trees.c:387)
  1239. [6] 0.0 0.00 0.00 13496 init_block (trees.c:408)
  1240. @end smallexample
  1241. @node Annotated Source
  1242. @section The Annotated Source Listing
  1243. @code{gprof}'s @samp{-A} option triggers an annotated source listing,
  1244. which lists the program's source code, each function labeled with the
  1245. number of times it was called. You may also need to specify the
  1246. @samp{-I} option, if @code{gprof} can't find the source code files.
  1247. With older versions of @code{gcc} compiling with @samp{gcc @dots{} -g
  1248. -pg -a} augments your program with basic-block counting code, in
  1249. addition to function counting code. This enables @code{gprof} to
  1250. determine how many times each line of code was executed. With newer
  1251. versions of @code{gcc} support for displaying basic-block counts is
  1252. provided by the @code{gcov} program.
  1253. For example, consider the following function, taken from gzip,
  1254. with line numbers added:
  1255. @smallexample
  1256. 1 ulg updcrc(s, n)
  1257. 2 uch *s;
  1258. 3 unsigned n;
  1259. 4 @{
  1260. 5 register ulg c;
  1261. 6
  1262. 7 static ulg crc = (ulg)0xffffffffL;
  1263. 8
  1264. 9 if (s == NULL) @{
  1265. 10 c = 0xffffffffL;
  1266. 11 @} else @{
  1267. 12 c = crc;
  1268. 13 if (n) do @{
  1269. 14 c = crc_32_tab[...];
  1270. 15 @} while (--n);
  1271. 16 @}
  1272. 17 crc = c;
  1273. 18 return c ^ 0xffffffffL;
  1274. 19 @}
  1275. @end smallexample
  1276. @code{updcrc} has at least five basic-blocks.
  1277. One is the function itself. The
  1278. @code{if} statement on line 9 generates two more basic-blocks, one
  1279. for each branch of the @code{if}. A fourth basic-block results from
  1280. the @code{if} on line 13, and the contents of the @code{do} loop form
  1281. the fifth basic-block. The compiler may also generate additional
  1282. basic-blocks to handle various special cases.
  1283. A program augmented for basic-block counting can be analyzed with
  1284. @samp{gprof -l -A}.
  1285. The @samp{-x} option is also helpful,
  1286. to ensure that each line of code is labeled at least once.
  1287. Here is @code{updcrc}'s
  1288. annotated source listing for a sample @code{gzip} run:
  1289. @smallexample
  1290. ulg updcrc(s, n)
  1291. uch *s;
  1292. unsigned n;
  1293. 2 ->@{
  1294. register ulg c;
  1295. static ulg crc = (ulg)0xffffffffL;
  1296. 2 -> if (s == NULL) @{
  1297. 1 -> c = 0xffffffffL;
  1298. 1 -> @} else @{
  1299. 1 -> c = crc;
  1300. 1 -> if (n) do @{
  1301. 26312 -> c = crc_32_tab[...];
  1302. 26312,1,26311 -> @} while (--n);
  1303. @}
  1304. 2 -> crc = c;
  1305. 2 -> return c ^ 0xffffffffL;
  1306. 2 ->@}
  1307. @end smallexample
  1308. In this example, the function was called twice, passing once through
  1309. each branch of the @code{if} statement. The body of the @code{do}
  1310. loop was executed a total of 26312 times. Note how the @code{while}
  1311. statement is annotated. It began execution 26312 times, once for
  1312. each iteration through the loop. One of those times (the last time)
  1313. it exited, while it branched back to the beginning of the loop 26311 times.
  1314. @node Inaccuracy
  1315. @chapter Inaccuracy of @code{gprof} Output
  1316. @menu
  1317. * Sampling Error:: Statistical margins of error
  1318. * Assumptions:: Estimating children times
  1319. @end menu
  1320. @node Sampling Error
  1321. @section Statistical Sampling Error
  1322. The run-time figures that @code{gprof} gives you are based on a sampling
  1323. process, so they are subject to statistical inaccuracy. If a function runs
  1324. only a small amount of time, so that on the average the sampling process
  1325. ought to catch that function in the act only once, there is a pretty good
  1326. chance it will actually find that function zero times, or twice.
  1327. By contrast, the number-of-calls and basic-block figures are derived
  1328. by counting, not sampling. They are completely accurate and will not
  1329. vary from run to run if your program is deterministic and single
  1330. threaded. In multi-threaded applications, or single threaded
  1331. applications that link with multi-threaded libraries, the counts are
  1332. only deterministic if the counting function is thread-safe. (Note:
  1333. beware that the mcount counting function in glibc is @emph{not}
  1334. thread-safe). @xref{Implementation, ,Implementation of Profiling}.
  1335. The @dfn{sampling period} that is printed at the beginning of the flat
  1336. profile says how often samples are taken. The rule of thumb is that a
  1337. run-time figure is accurate if it is considerably bigger than the sampling
  1338. period.
  1339. The actual amount of error can be predicted.
  1340. For @var{n} samples, the @emph{expected} error
  1341. is the square-root of @var{n}. For example,
  1342. if the sampling period is 0.01 seconds and @code{foo}'s run-time is 1 second,
  1343. @var{n} is 100 samples (1 second/0.01 seconds), sqrt(@var{n}) is 10 samples, so
  1344. the expected error in @code{foo}'s run-time is 0.1 seconds (10*0.01 seconds),
  1345. or ten percent of the observed value.
  1346. Again, if the sampling period is 0.01 seconds and @code{bar}'s run-time is
  1347. 100 seconds, @var{n} is 10000 samples, sqrt(@var{n}) is 100 samples, so
  1348. the expected error in @code{bar}'s run-time is 1 second,
  1349. or one percent of the observed value.
  1350. It is likely to
  1351. vary this much @emph{on the average} from one profiling run to the next.
  1352. (@emph{Sometimes} it will vary more.)
  1353. This does not mean that a small run-time figure is devoid of information.
  1354. If the program's @emph{total} run-time is large, a small run-time for one
  1355. function does tell you that that function used an insignificant fraction of
  1356. the whole program's time. Usually this means it is not worth optimizing.
  1357. One way to get more accuracy is to give your program more (but similar)
  1358. input data so it will take longer. Another way is to combine the data from
  1359. several runs, using the @samp{-s} option of @code{gprof}. Here is how:
  1360. @enumerate
  1361. @item
  1362. Run your program once.
  1363. @item
  1364. Issue the command @samp{mv gmon.out gmon.sum}.
  1365. @item
  1366. Run your program again, the same as before.
  1367. @item
  1368. Merge the new data in @file{gmon.out} into @file{gmon.sum} with this command:
  1369. @example
  1370. gprof -s @var{executable-file} gmon.out gmon.sum
  1371. @end example
  1372. @item
  1373. Repeat the last two steps as often as you wish.
  1374. @item
  1375. Analyze the cumulative data using this command:
  1376. @example
  1377. gprof @var{executable-file} gmon.sum > @var{output-file}
  1378. @end example
  1379. @end enumerate
  1380. @node Assumptions
  1381. @section Estimating @code{children} Times
  1382. Some of the figures in the call graph are estimates---for example, the
  1383. @code{children} time values and all the time figures in caller and
  1384. subroutine lines.
  1385. There is no direct information about these measurements in the profile
  1386. data itself. Instead, @code{gprof} estimates them by making an assumption
  1387. about your program that might or might not be true.
  1388. The assumption made is that the average time spent in each call to any
  1389. function @code{foo} is not correlated with who called @code{foo}. If
  1390. @code{foo} used 5 seconds in all, and 2/5 of the calls to @code{foo} came
  1391. from @code{a}, then @code{foo} contributes 2 seconds to @code{a}'s
  1392. @code{children} time, by assumption.
  1393. This assumption is usually true enough, but for some programs it is far
  1394. from true. Suppose that @code{foo} returns very quickly when its argument
  1395. is zero; suppose that @code{a} always passes zero as an argument, while
  1396. other callers of @code{foo} pass other arguments. In this program, all the
  1397. time spent in @code{foo} is in the calls from callers other than @code{a}.
  1398. But @code{gprof} has no way of knowing this; it will blindly and
  1399. incorrectly charge 2 seconds of time in @code{foo} to the children of
  1400. @code{a}.
  1401. @c FIXME - has this been fixed?
  1402. We hope some day to put more complete data into @file{gmon.out}, so that
  1403. this assumption is no longer needed, if we can figure out how. For the
  1404. novice, the estimated figures are usually more useful than misleading.
  1405. @node How do I?
  1406. @chapter Answers to Common Questions
  1407. @table @asis
  1408. @item How can I get more exact information about hot spots in my program?
  1409. Looking at the per-line call counts only tells part of the story.
  1410. Because @code{gprof} can only report call times and counts by function,
  1411. the best way to get finer-grained information on where the program
  1412. is spending its time is to re-factor large functions into sequences
  1413. of calls to smaller ones. Beware however that this can introduce
  1414. artificial hot spots since compiling with @samp{-pg} adds a significant
  1415. overhead to function calls. An alternative solution is to use a
  1416. non-intrusive profiler, e.g.@: oprofile.
  1417. @item How do I find which lines in my program were executed the most times?
  1418. Use the @code{gcov} program.
  1419. @item How do I find which lines in my program called a particular function?
  1420. Use @samp{gprof -l} and lookup the function in the call graph.
  1421. The callers will be broken down by function and line number.
  1422. @item How do I analyze a program that runs for less than a second?
  1423. Try using a shell script like this one:
  1424. @example
  1425. for i in `seq 1 100`; do
  1426. fastprog
  1427. mv gmon.out gmon.out.$i
  1428. done
  1429. gprof -s fastprog gmon.out.*
  1430. gprof fastprog gmon.sum
  1431. @end example
  1432. If your program is completely deterministic, all the call counts
  1433. will be simple multiples of 100 (i.e., a function called once in
  1434. each run will appear with a call count of 100).
  1435. @end table
  1436. @node Incompatibilities
  1437. @chapter Incompatibilities with Unix @code{gprof}
  1438. @sc{gnu} @code{gprof} and Berkeley Unix @code{gprof} use the same data
  1439. file @file{gmon.out}, and provide essentially the same information. But
  1440. there are a few differences.
  1441. @itemize @bullet
  1442. @item
  1443. @sc{gnu} @code{gprof} uses a new, generalized file format with support
  1444. for basic-block execution counts and non-realtime histograms. A magic
  1445. cookie and version number allows @code{gprof} to easily identify
  1446. new style files. Old BSD-style files can still be read.
  1447. @xref{File Format, ,Profiling Data File Format}.
  1448. @item
  1449. For a recursive function, Unix @code{gprof} lists the function as a
  1450. parent and as a child, with a @code{calls} field that lists the number
  1451. of recursive calls. @sc{gnu} @code{gprof} omits these lines and puts
  1452. the number of recursive calls in the primary line.
  1453. @item
  1454. When a function is suppressed from the call graph with @samp{-e}, @sc{gnu}
  1455. @code{gprof} still lists it as a subroutine of functions that call it.
  1456. @item
  1457. @sc{gnu} @code{gprof} accepts the @samp{-k} with its argument
  1458. in the form @samp{from/to}, instead of @samp{from to}.
  1459. @item
  1460. In the annotated source listing,
  1461. if there are multiple basic blocks on the same line,
  1462. @sc{gnu} @code{gprof} prints all of their counts, separated by commas.
  1463. @ignore - it does this now
  1464. @item
  1465. The function names printed in @sc{gnu} @code{gprof} output do not include
  1466. the leading underscores that are added internally to the front of all
  1467. C identifiers on many operating systems.
  1468. @end ignore
  1469. @item
  1470. The blurbs, field widths, and output formats are different. @sc{gnu}
  1471. @code{gprof} prints blurbs after the tables, so that you can see the
  1472. tables without skipping the blurbs.
  1473. @end itemize
  1474. @node Details
  1475. @chapter Details of Profiling
  1476. @menu
  1477. * Implementation:: How a program collects profiling information
  1478. * File Format:: Format of @samp{gmon.out} files
  1479. * Internals:: @code{gprof}'s internal operation
  1480. * Debugging:: Using @code{gprof}'s @samp{-d} option
  1481. @end menu
  1482. @node Implementation
  1483. @section Implementation of Profiling
  1484. Profiling works by changing how every function in your program is compiled
  1485. so that when it is called, it will stash away some information about where
  1486. it was called from. From this, the profiler can figure out what function
  1487. called it, and can count how many times it was called. This change is made
  1488. by the compiler when your program is compiled with the @samp{-pg} option,
  1489. which causes every function to call @code{mcount}
  1490. (or @code{_mcount}, or @code{__mcount}, depending on the OS and compiler)
  1491. as one of its first operations.
  1492. The @code{mcount} routine, included in the profiling library,
  1493. is responsible for recording in an in-memory call graph table
  1494. both its parent routine (the child) and its parent's parent. This is
  1495. typically done by examining the stack frame to find both
  1496. the address of the child, and the return address in the original parent.
  1497. Since this is a very machine-dependent operation, @code{mcount}
  1498. itself is typically a short assembly-language stub routine
  1499. that extracts the required
  1500. information, and then calls @code{__mcount_internal}
  1501. (a normal C function) with two arguments---@code{frompc} and @code{selfpc}.
  1502. @code{__mcount_internal} is responsible for maintaining
  1503. the in-memory call graph, which records @code{frompc}, @code{selfpc},
  1504. and the number of times each of these call arcs was traversed.
  1505. GCC Version 2 provides a magical function (@code{__builtin_return_address}),
  1506. which allows a generic @code{mcount} function to extract the
  1507. required information from the stack frame. However, on some
  1508. architectures, most notably the SPARC, using this builtin can be
  1509. very computationally expensive, and an assembly language version
  1510. of @code{mcount} is used for performance reasons.
  1511. Number-of-calls information for library routines is collected by using a
  1512. special version of the C library. The programs in it are the same as in
  1513. the usual C library, but they were compiled with @samp{-pg}. If you
  1514. link your program with @samp{gcc @dots{} -pg}, it automatically uses the
  1515. profiling version of the library.
  1516. Profiling also involves watching your program as it runs, and keeping a
  1517. histogram of where the program counter happens to be every now and then.
  1518. Typically the program counter is looked at around 100 times per second of
  1519. run time, but the exact frequency may vary from system to system.
  1520. This is done is one of two ways. Most UNIX-like operating systems
  1521. provide a @code{profil()} system call, which registers a memory
  1522. array with the kernel, along with a scale
  1523. factor that determines how the program's address space maps
  1524. into the array.
  1525. Typical scaling values cause every 2 to 8 bytes of address space
  1526. to map into a single array slot.
  1527. On every tick of the system clock
  1528. (assuming the profiled program is running), the value of the
  1529. program counter is examined and the corresponding slot in
  1530. the memory array is incremented. Since this is done in the kernel,
  1531. which had to interrupt the process anyway to handle the clock
  1532. interrupt, very little additional system overhead is required.
  1533. However, some operating systems, most notably Linux 2.0 (and earlier),
  1534. do not provide a @code{profil()} system call. On such a system,
  1535. arrangements are made for the kernel to periodically deliver
  1536. a signal to the process (typically via @code{setitimer()}),
  1537. which then performs the same operation of examining the
  1538. program counter and incrementing a slot in the memory array.
  1539. Since this method requires a signal to be delivered to
  1540. user space every time a sample is taken, it uses considerably
  1541. more overhead than kernel-based profiling. Also, due to the
  1542. added delay required to deliver the signal, this method is
  1543. less accurate as well.
  1544. A special startup routine allocates memory for the histogram and
  1545. either calls @code{profil()} or sets up
  1546. a clock signal handler.
  1547. This routine (@code{monstartup}) can be invoked in several ways.
  1548. On Linux systems, a special profiling startup file @code{gcrt0.o},
  1549. which invokes @code{monstartup} before @code{main},
  1550. is used instead of the default @code{crt0.o}.
  1551. Use of this special startup file is one of the effects
  1552. of using @samp{gcc @dots{} -pg} to link.
  1553. On SPARC systems, no special startup files are used.
  1554. Rather, the @code{mcount} routine, when it is invoked for
  1555. the first time (typically when @code{main} is called),
  1556. calls @code{monstartup}.
  1557. If the compiler's @samp{-a} option was used, basic-block counting
  1558. is also enabled. Each object file is then compiled with a static array
  1559. of counts, initially zero.
  1560. In the executable code, every time a new basic-block begins
  1561. (i.e., when an @code{if} statement appears), an extra instruction
  1562. is inserted to increment the corresponding count in the array.
  1563. At compile time, a paired array was constructed that recorded
  1564. the starting address of each basic-block. Taken together,
  1565. the two arrays record the starting address of every basic-block,
  1566. along with the number of times it was executed.
  1567. The profiling library also includes a function (@code{mcleanup}) which is
  1568. typically registered using @code{atexit()} to be called as the
  1569. program exits, and is responsible for writing the file @file{gmon.out}.
  1570. Profiling is turned off, various headers are output, and the histogram
  1571. is written, followed by the call-graph arcs and the basic-block counts.
  1572. The output from @code{gprof} gives no indication of parts of your program that
  1573. are limited by I/O or swapping bandwidth. This is because samples of the
  1574. program counter are taken at fixed intervals of the program's run time.
  1575. Therefore, the
  1576. time measurements in @code{gprof} output say nothing about time that your
  1577. program was not running. For example, a part of the program that creates
  1578. so much data that it cannot all fit in physical memory at once may run very
  1579. slowly due to thrashing, but @code{gprof} will say it uses little time. On
  1580. the other hand, sampling by run time has the advantage that the amount of
  1581. load due to other users won't directly affect the output you get.
  1582. @node File Format
  1583. @section Profiling Data File Format
  1584. The old BSD-derived file format used for profile data does not contain a
  1585. magic cookie that allows one to check whether a data file really is a
  1586. @code{gprof} file. Furthermore, it does not provide a version number, thus
  1587. rendering changes to the file format almost impossible. @sc{gnu} @code{gprof}
  1588. uses a new file format that provides these features. For backward
  1589. compatibility, @sc{gnu} @code{gprof} continues to support the old BSD-derived
  1590. format, but not all features are supported with it. For example,
  1591. basic-block execution counts cannot be accommodated by the old file
  1592. format.
  1593. The new file format is defined in header file @file{gmon_out.h}. It
  1594. consists of a header containing the magic cookie and a version number,
  1595. as well as some spare bytes available for future extensions. All data
  1596. in a profile data file is in the native format of the target for which
  1597. the profile was collected. @sc{gnu} @code{gprof} adapts automatically
  1598. to the byte-order in use.
  1599. In the new file format, the header is followed by a sequence of
  1600. records. Currently, there are three different record types: histogram
  1601. records, call-graph arc records, and basic-block execution count
  1602. records. Each file can contain any number of each record type. When
  1603. reading a file, @sc{gnu} @code{gprof} will ensure records of the same type are
  1604. compatible with each other and compute the union of all records. For
  1605. example, for basic-block execution counts, the union is simply the sum
  1606. of all execution counts for each basic-block.
  1607. @subsection Histogram Records
  1608. Histogram records consist of a header that is followed by an array of
  1609. bins. The header contains the text-segment range that the histogram
  1610. spans, the size of the histogram in bytes (unlike in the old BSD
  1611. format, this does not include the size of the header), the rate of the
  1612. profiling clock, and the physical dimension that the bin counts
  1613. represent after being scaled by the profiling clock rate. The
  1614. physical dimension is specified in two parts: a long name of up to 15
  1615. characters and a single character abbreviation. For example, a
  1616. histogram representing real-time would specify the long name as
  1617. ``seconds'' and the abbreviation as ``s''. This feature is useful for
  1618. architectures that support performance monitor hardware (which,
  1619. fortunately, is becoming increasingly common). For example, under DEC
  1620. OSF/1, the ``uprofile'' command can be used to produce a histogram of,
  1621. say, instruction cache misses. In this case, the dimension in the
  1622. histogram header could be set to ``i-cache misses'' and the abbreviation
  1623. could be set to ``1'' (because it is simply a count, not a physical
  1624. dimension). Also, the profiling rate would have to be set to 1 in
  1625. this case.
  1626. Histogram bins are 16-bit numbers and each bin represent an equal
  1627. amount of text-space. For example, if the text-segment is one
  1628. thousand bytes long and if there are ten bins in the histogram, each
  1629. bin represents one hundred bytes.
  1630. @subsection Call-Graph Records
  1631. Call-graph records have a format that is identical to the one used in
  1632. the BSD-derived file format. It consists of an arc in the call graph
  1633. and a count indicating the number of times the arc was traversed
  1634. during program execution. Arcs are specified by a pair of addresses:
  1635. the first must be within caller's function and the second must be
  1636. within the callee's function. When performing profiling at the
  1637. function level, these addresses can point anywhere within the
  1638. respective function. However, when profiling at the line-level, it is
  1639. better if the addresses are as close to the call-site/entry-point as
  1640. possible. This will ensure that the line-level call-graph is able to
  1641. identify exactly which line of source code performed calls to a
  1642. function.
  1643. @subsection Basic-Block Execution Count Records
  1644. Basic-block execution count records consist of a header followed by a
  1645. sequence of address/count pairs. The header simply specifies the
  1646. length of the sequence. In an address/count pair, the address
  1647. identifies a basic-block and the count specifies the number of times
  1648. that basic-block was executed. Any address within the basic-address can
  1649. be used.
  1650. @node Internals
  1651. @section @code{gprof}'s Internal Operation
  1652. Like most programs, @code{gprof} begins by processing its options.
  1653. During this stage, it may building its symspec list
  1654. (@code{sym_ids.c:@-sym_id_add}), if
  1655. options are specified which use symspecs.
  1656. @code{gprof} maintains a single linked list of symspecs,
  1657. which will eventually get turned into 12 symbol tables,
  1658. organized into six include/exclude pairs---one
  1659. pair each for the flat profile (INCL_FLAT/EXCL_FLAT),
  1660. the call graph arcs (INCL_ARCS/EXCL_ARCS),
  1661. printing in the call graph (INCL_GRAPH/EXCL_GRAPH),
  1662. timing propagation in the call graph (INCL_TIME/EXCL_TIME),
  1663. the annotated source listing (INCL_ANNO/EXCL_ANNO),
  1664. and the execution count listing (INCL_EXEC/EXCL_EXEC).
  1665. After option processing, @code{gprof} finishes
  1666. building the symspec list by adding all the symspecs in
  1667. @code{default_excluded_list} to the exclude lists
  1668. EXCL_TIME and EXCL_GRAPH, and if line-by-line profiling is specified,
  1669. EXCL_FLAT as well.
  1670. These default excludes are not added to EXCL_ANNO, EXCL_ARCS, and EXCL_EXEC.
  1671. Next, the BFD library is called to open the object file,
  1672. verify that it is an object file,
  1673. and read its symbol table (@code{core.c:@-core_init}),
  1674. using @code{bfd_canonicalize_symtab} after mallocing
  1675. an appropriately sized array of symbols. At this point,
  1676. function mappings are read (if the @samp{--file-ordering} option
  1677. has been specified), and the core text space is read into
  1678. memory (if the @samp{-c} option was given).
  1679. @code{gprof}'s own symbol table, an array of Sym structures,
  1680. is now built.
  1681. This is done in one of two ways, by one of two routines, depending
  1682. on whether line-by-line profiling (@samp{-l} option) has been
  1683. enabled.
  1684. For normal profiling, the BFD canonical symbol table is scanned.
  1685. For line-by-line profiling, every
  1686. text space address is examined, and a new symbol table entry
  1687. gets created every time the line number changes.
  1688. In either case, two passes are made through the symbol
  1689. table---one to count the size of the symbol table required,
  1690. and the other to actually read the symbols. In between the
  1691. two passes, a single array of type @code{Sym} is created of
  1692. the appropriate length.
  1693. Finally, @code{symtab.c:@-symtab_finalize}
  1694. is called to sort the symbol table and remove duplicate entries
  1695. (entries with the same memory address).
  1696. The symbol table must be a contiguous array for two reasons.
  1697. First, the @code{qsort} library function (which sorts an array)
  1698. will be used to sort the symbol table.
  1699. Also, the symbol lookup routine (@code{symtab.c:@-sym_lookup}),
  1700. which finds symbols
  1701. based on memory address, uses a binary search algorithm
  1702. which requires the symbol table to be a sorted array.
  1703. Function symbols are indicated with an @code{is_func} flag.
  1704. Line number symbols have no special flags set.
  1705. Additionally, a symbol can have an @code{is_static} flag
  1706. to indicate that it is a local symbol.
  1707. With the symbol table read, the symspecs can now be translated
  1708. into Syms (@code{sym_ids.c:@-sym_id_parse}). Remember that a single
  1709. symspec can match multiple symbols.
  1710. An array of symbol tables
  1711. (@code{syms}) is created, each entry of which is a symbol table
  1712. of Syms to be included or excluded from a particular listing.
  1713. The master symbol table and the symspecs are examined by nested
  1714. loops, and every symbol that matches a symspec is inserted
  1715. into the appropriate syms table. This is done twice, once to
  1716. count the size of each required symbol table, and again to build
  1717. the tables, which have been malloced between passes.
  1718. From now on, to determine whether a symbol is on an include
  1719. or exclude symspec list, @code{gprof} simply uses its
  1720. standard symbol lookup routine on the appropriate table
  1721. in the @code{syms} array.
  1722. Now the profile data file(s) themselves are read
  1723. (@code{gmon_io.c:@-gmon_out_read}),
  1724. first by checking for a new-style @samp{gmon.out} header,
  1725. then assuming this is an old-style BSD @samp{gmon.out}
  1726. if the magic number test failed.
  1727. New-style histogram records are read by @code{hist.c:@-hist_read_rec}.
  1728. For the first histogram record, allocate a memory array to hold
  1729. all the bins, and read them in.
  1730. When multiple profile data files (or files with multiple histogram
  1731. records) are read, the memory ranges of each pair of histogram records
  1732. must be either equal, or non-overlapping. For each pair of histogram
  1733. records, the resolution (memory region size divided by the number of
  1734. bins) must be the same. The time unit must be the same for all
  1735. histogram records. If the above containts are met, all histograms
  1736. for the same memory range are merged.
  1737. As each call graph record is read (@code{call_graph.c:@-cg_read_rec}),
  1738. the parent and child addresses
  1739. are matched to symbol table entries, and a call graph arc is
  1740. created by @code{cg_arcs.c:@-arc_add}, unless the arc fails a symspec
  1741. check against INCL_ARCS/EXCL_ARCS. As each arc is added,
  1742. a linked list is maintained of the parent's child arcs, and of the child's
  1743. parent arcs.
  1744. Both the child's call count and the arc's call count are
  1745. incremented by the record's call count.
  1746. Basic-block records are read (@code{basic_blocks.c:@-bb_read_rec}),
  1747. but only if line-by-line profiling has been selected.
  1748. Each basic-block address is matched to a corresponding line
  1749. symbol in the symbol table, and an entry made in the symbol's
  1750. bb_addr and bb_calls arrays. Again, if multiple basic-block
  1751. records are present for the same address, the call counts
  1752. are cumulative.
  1753. A gmon.sum file is dumped, if requested (@code{gmon_io.c:@-gmon_out_write}).
  1754. If histograms were present in the data files, assign them to symbols
  1755. (@code{hist.c:@-hist_assign_samples}) by iterating over all the sample
  1756. bins and assigning them to symbols. Since the symbol table
  1757. is sorted in order of ascending memory addresses, we can
  1758. simple follow along in the symbol table as we make our pass
  1759. over the sample bins.
  1760. This step includes a symspec check against INCL_FLAT/EXCL_FLAT.
  1761. Depending on the histogram
  1762. scale factor, a sample bin may span multiple symbols,
  1763. in which case a fraction of the sample count is allocated
  1764. to each symbol, proportional to the degree of overlap.
  1765. This effect is rare for normal profiling, but overlaps
  1766. are more common during line-by-line profiling, and can
  1767. cause each of two adjacent lines to be credited with half
  1768. a hit, for example.
  1769. If call graph data is present, @code{cg_arcs.c:@-cg_assemble} is called.
  1770. First, if @samp{-c} was specified, a machine-dependent
  1771. routine (@code{find_call}) scans through each symbol's machine code,
  1772. looking for subroutine call instructions, and adding them
  1773. to the call graph with a zero call count.
  1774. A topological sort is performed by depth-first numbering
  1775. all the symbols (@code{cg_dfn.c:@-cg_dfn}), so that
  1776. children are always numbered less than their parents,
  1777. then making a array of pointers into the symbol table and sorting it into
  1778. numerical order, which is reverse topological
  1779. order (children appear before parents).
  1780. Cycles are also detected at this point, all members
  1781. of which are assigned the same topological number.
  1782. Two passes are now made through this sorted array of symbol pointers.
  1783. The first pass, from end to beginning (parents to children),
  1784. computes the fraction of child time to propagate to each parent
  1785. and a print flag.
  1786. The print flag reflects symspec handling of INCL_GRAPH/EXCL_GRAPH,
  1787. with a parent's include or exclude (print or no print) property
  1788. being propagated to its children, unless they themselves explicitly appear
  1789. in INCL_GRAPH or EXCL_GRAPH.
  1790. A second pass, from beginning to end (children to parents) actually
  1791. propagates the timings along the call graph, subject
  1792. to a check against INCL_TIME/EXCL_TIME.
  1793. With the print flag, fractions, and timings now stored in the symbol
  1794. structures, the topological sort array is now discarded, and a
  1795. new array of pointers is assembled, this time sorted by propagated time.
  1796. Finally, print the various outputs the user requested, which is now fairly
  1797. straightforward. The call graph (@code{cg_print.c:@-cg_print}) and
  1798. flat profile (@code{hist.c:@-hist_print}) are regurgitations of values
  1799. already computed. The annotated source listing
  1800. (@code{basic_blocks.c:@-print_annotated_source}) uses basic-block
  1801. information, if present, to label each line of code with call counts,
  1802. otherwise only the function call counts are presented.
  1803. The function ordering code is marginally well documented
  1804. in the source code itself (@code{cg_print.c}). Basically,
  1805. the functions with the most use and the most parents are
  1806. placed first, followed by other functions with the most use,
  1807. followed by lower use functions, followed by unused functions
  1808. at the end.
  1809. @node Debugging
  1810. @section Debugging @code{gprof}
  1811. If @code{gprof} was compiled with debugging enabled,
  1812. the @samp{-d} option triggers debugging output
  1813. (to stdout) which can be helpful in understanding its operation.
  1814. The debugging number specified is interpreted as a sum of the following
  1815. options:
  1816. @table @asis
  1817. @item 2 - Topological sort
  1818. Monitor depth-first numbering of symbols during call graph analysis
  1819. @item 4 - Cycles
  1820. Shows symbols as they are identified as cycle heads
  1821. @item 16 - Tallying
  1822. As the call graph arcs are read, show each arc and how
  1823. the total calls to each function are tallied
  1824. @item 32 - Call graph arc sorting
  1825. Details sorting individual parents/children within each call graph entry
  1826. @item 64 - Reading histogram and call graph records
  1827. Shows address ranges of histograms as they are read, and each
  1828. call graph arc
  1829. @item 128 - Symbol table
  1830. Reading, classifying, and sorting the symbol table from the object file.
  1831. For line-by-line profiling (@samp{-l} option), also shows line numbers
  1832. being assigned to memory addresses.
  1833. @item 256 - Static call graph
  1834. Trace operation of @samp{-c} option
  1835. @item 512 - Symbol table and arc table lookups
  1836. Detail operation of lookup routines
  1837. @item 1024 - Call graph propagation
  1838. Shows how function times are propagated along the call graph
  1839. @item 2048 - Basic-blocks
  1840. Shows basic-block records as they are read from profile data
  1841. (only meaningful with @samp{-l} option)
  1842. @item 4096 - Symspecs
  1843. Shows symspec-to-symbol pattern matching operation
  1844. @item 8192 - Annotate source
  1845. Tracks operation of @samp{-A} option
  1846. @end table
  1847. @node GNU Free Documentation License
  1848. @appendix GNU Free Documentation License
  1849. @include fdl.texi
  1850. @bye
  1851. NEEDS AN INDEX
  1852. -T - "traditional BSD style": How is it different? Should the
  1853. differences be documented?
  1854. example flat file adds up to 100.01%...
  1855. note: time estimates now only go out to one decimal place (0.0), where
  1856. they used to extend two (78.67).