\title{QQ: Nanoscale Timing and Profiling}
\authors {James Frye \and James G. King \and Christine J. Wilson \and 
Fredrick C. Harris, Jr.}

Submitted for the 4th International Workshop on Performance Modeling, 
Evaluation, and Optimization of Parallel and Distributed Systems 
(PMEO-PDS'05) To be held in conjunction with IPDPS 2005

\section{Abstract}
QQ is set of tools for timing and memory profiling capable of analysis
at nanoscale time resolution.  It is platform independent and useful 
for either sequential, distributed, or parallel programs.  The output 
can be visualized using various graphics packages.  Currently QQ 
utilizes the IA32 hardware architecture to monitor performance but can be
readily ported to other hardware.  QQ can be implemented and customized
quickly and is scalable.

\section{Introduction}
When developing a complex program that requires massive computational
power, proper tracking of performance is crucial for development.  
Effective optimization requires some means of accurately measuring the
effects of code changes quickly.

An example of a complex system is the NeoCortical Simulator (NCS) \cite
{wgh01:ncs-siam,whg01:ncs-sc, thesis:ecwilson}.  It is a large-scale 
biologically realistic simulator of cortical neurons.  It has simulated 
biological neural networks with $10^6$ cells and $10^9$ synaptic 
connections successfully. \cite {matt1}  Since NCS utilizes the fastest
available hardware for processing and internodal communication, the 
code was the only place where we could make significant performance 
improvements.  Optimization is crucial since a goal for NCS is that the 
simulations approach real-time processing speeds.  Therefore, 
considerable effort has been devoted to optimizing the code for both 
speed and memory utilization \cite {thesis:jf}.

A review of the currently available software packages for temporal 
profiling quickly lead to the need for a new set of tools.  The 
available performance monitors that were reviewed included TAU
Portable Profiling Package \cite{tau}, and SvPablo: A multi-Language
Performance Analysis System \cite{derose98svpablo}.  TAU is compact and
able to trace individual user-defined code blocks.  It also utilizes 
hardware counters, but relies on pre-compiling code to embed the timing
commands using a pre-compiler that is not compatible with gcc.  SvPablo 
utilized hardware counters like QQ, but the graphical interface and 
meta-meta-format output was more than what was necessary for our 
analysis.

QQ was developed as a set of tools that can accurately measure either
elapsed time or number of machine instructions executed, and memory 
usage, with a minimum of overhead.  The name QQ is not an acronym but
was chosen as a name prefix simply because the letter Q is seldom used
as the first letter of a variable or function name and would minimize
potential conflicts with existing code.  QQ was used extensively in the
development and optimization of NCS, and has been applied to a number of
other programs.

The organization of this paper is as follows:  Section 2 will address
the design considerations and implementation of QQ.  Section 3 covers
the what QQ's capabilities are and defines its features.  Also, some 
examples for output and output processing are included in this section.
Section 4 covers examples of QQ in action.  An example of its use
in a sequential and parallel program are detailed.  Section 5 defines
the future work and direction of development of the QQ tools.

\section {QQ Design}

Nanoscale Timing

Straightforward measurement of NCS elements is difficult.  Different 
algorithms contribute varying numbers of elements in an input-dependent
sequence.  This makes NCS unlike other compute-intensive programs that
mainly consist of a few loops iterating many times over the same code.
Performance is not adequately measured by a relatively coarse-grained 
tool such as gprof /cite{gprof}. The documented gprof resolution is 
approximately a hundredth of a millisecond or $10^-5$ seconds.  And 
current system timing routines (Linux \code{gettimeofday},\code{MPI\
_Wtime}, etc.) typically measure to an accuracy of, at best, 
microseconds ($10^-6$ seconds).  At current processor speeds, this 
translates to a granularity of several thousands of instructions.

NCS demanded precise timing measurements on the order of tens or 
hundreds of machine cycles, or $10^-9$ seconds.  Therefore, without
the resolution provide by the QQ tools, the effect of a change to any
single element may have been overlooked.  


Hardware Time Stamp Counter

Most modern microprocessors include a hardware based time stamp counter.
NCS is currently compiled for use on the Intel IA32 (Pentium) architecture.
Each processor contains a 64-bit hardware counter, which is zeroed when
the processor is booted, and thereafter increments every clock cycle.
The chance that the program would run long enough to roll the counter
over again is not a problem since at current processor speeds the 64-bit 
counter would roll over once in a century.  The IA32 instruction set
provides the \code {RDTSC} instruction, which stores the time stamp 
counter contents into the \code {edx:eax} register pair.  Subtracting 
the values of two successive calls to this instruction thus gives a 
count of processor cycles.  The actual elapsed time is derived by 
division by the clock frequency and is theoretically accurate to the
processor clock frequency, or (at current CPU speeds) a fraction of a
nanosecond.

Factors such as pipelining and out-of-order execution reduce the 
accuracy to several tens of clock cycles.  Although steps such as 
issuing serializing instructions bracketing a code section can be 
taken to reduce the impact of this type of overhead, these steps alter 
the timing of the code being measured.

By itself, the \code {RDTSC} instruction, or its cognates in other
architectures, provides a simple means of measuring the elapsed time
between two points in a program.  This is a useful and important 
performance measurement.  Post-processing routines can process
the data to provide elapsed time in seconds or clock cycles.


\subsection {Sequential Profiling}

Frequently it is necessary to collect more detailed information, for
example, marking the time at which a particular event occurs, or tracing the amount of 
time spent within a repeatedly called section of code.  A 
major consideration was to reduce overhead associated with the monitor.
Instrumentation calls were included in a non-obtrusive way and 
included in the code via a simple compile flag \code{QQ\_ENABLE}.

QQ is based on the notion of tracing named events.  Each event is 
characterized by a key, which identifies the particular event, and an 
event time.  In addition, depending on the type of event, a value, 
count or state flag may be necessary.  The different event types are 
combined into an event union.

When the profiler is initialized by calling the QQInit function, it
allocates memory for a user-specified number of events, initializes the
event pointer to the first event, and sets the base time to the current
\code{RDTSC} value.

After initialization, one or more of the \code{QQAdd*} functions are
called to add event types to the internal name table.  Each function is
passed a name (character string) for the type of event, and returns the
integer key for the event.  These keys are variables in the program 
space, and are the only remnants of QQ that remain in code when 
compiled with the \code{QQ\_ENABLE} flag off.

The individual event recording functions are thus reduced to a minimum:
each checks to see if the event pointer has overflowed the allocated
buffer.  If not, the \code{RDTSC} instruction is called, the key,
count, and any other information is written to the current event, and the
event counter is incremented.

The \code{QQRecord} function allows event recording to be turned off and on
under program control.  It does this by caching the current event pointer
and replacing it with a value greater than the maximum allocated, thus
allowing the event recording functions to use a single test to determine
whether or not an event is to be recorded.

When profiling has finished, the \code{QQOut} function is called to write
the saved event information to a file.  


\subsection {Parallel Profiling}

For parallel programs, additional steps needed to be taken.  The 
initialization does an \code {MPI\_Barrier} call to synchronize, as 
nearly as possible, timings on all nodes.

Each node has its own event buffer, recording an independent set
of events.

On output, the buffers from all nodes are combined into a single file,
along with information to identify each node.  This file can later be
read and the information converted to a specified format for analysis.

\subsection{Profiling Memory Use}

Profiling Memory Allocation

Profiling memory usage is more difficult than profiling execution time.
At this time a completely satisfactory solution seems impossible.  
However, QQ has tried to gather as much useful information as possible.

For example, in a Linux system, it is possible to obtain the total 
memory allocated to a process at any point in time by reading the 
\code{statm} pseudo-file in the process directory of the \code{/proc} 
filesystem.  From this file, the number of 4 KByte pages allocated to 
the process can be read.  While this number includes both code and data
space, and may include the total memory allocated rather than what is 
currently in use, this value can be considered an upper boundary value.

The \code{GetMemoryUsed} function uses the previously mentioned method 
to return the total memory allocated to the program at the time when 
the function is called.  By recording memory usage values prior, during
and after a specific block of code is executed, it is possible to 
obtain a reasonable idea of how much memory is being used by that particular block of code.  However, it
does not allow for direct measurements on the scale of individual 
structures or objects.

The system allocates memory to a program in units of pages.  It is up to
the internal memory allocator (generally in the \code{malloc} library) to
parcel the pages into smaller units.  If this memory allocation is done
directly by calls to \code{malloc} library functions, it is easily
measured by using the preprocessor to redefine the function call to a
different function, which records allocation information and passes the
operation through to the actual allocation function.

Thus, for example, the \code{malloc} function can be redefined to be\\%
%
\begin{verbatim}
#ifdef MEM_STATS
    #define malloc(arg) MemMalloc (MEM_KEY, arg)
#endif
\end{verbatim}

Each call to malloc in the code now becomes a call to the
\code{MemMalloc} function, and the new call contains an additional
argument, which is the key under which the allocated memory will be
recorded.  Each chunk of allocated memory is stored in a C++ \code{map}
object, indexed by its address (the pointer value returned by the alloc
call). The call to \code{free} is redefined to remove the item
corresponding to the address from the map.  In this way, a consistent
record of all currently-allocated memory is maintained, and the record
for each item may contain information on the type of object, what routine
allocated it, and so forth.


Monitoring Object Creation

In principle it should be possible to do something similar to the above
for objects by overloading the new and delete operators, although we have
not yet done so.  Instead, a simpler method was used.

Each object constructor must have calls to the \code{MEMADDOBJECT}
and \code{MEMFREEOBJECT} routines added to them.  When memory profiling is turned
off, these calls evaluate to empty statements; when it is on, they evaluate
to calls to the memory recording functions and contain the object's this
pointer and the sizeof (this) value as arguments.

These functions allow most explicitly allocated memory and objects
defined in the code, to be recorded.  Memory that is allocated internally
by various library functions or standard C++ objects can not be recorded,
however.  The information available, although not complete, is still
quite useful.  If nothing else, the amount recorded as allocated by
the profiler can be compared to the total memory allocated to the
program.  If the two quantities are significantly different, the memory
is probably being allocated somewhere internally.



\section {Analysis Routines}

The timing interface includes many functions for tracing temporal 
events.  Figure XX shows the complete application programing interface 
currently available.  

Since the QQ tools are intended for programmers, the output was 
formatted to be flexible.  Most programmers prefer to write their own 
custom analysis code, or pipe the output to a general purpose tool such
as gnuplot /cite{gnuplot}, for example.  Unlike similar applications, 
the output was created to be flexible, precise and detailed, rather than
processed via predefined functions.  To this end, the output is stored
in binary in the following format.

Each block of code to be traced is given a key.  In the output file, 
the number of keys /code {nkeys(int)} is followed by the length of the
key name string, /code {keylen (int)}.  Then for each key, the 
following information is output, the index of the key, the key type 
and its name.  Then, the information regarding the nodes is output.
The number of nodes /code {nnodes(int)} is defined.  For each node 
the following information is output, the offset or index in file at 
which the data for the node starts, the number of entries for the node,
the base tick count for the node and the frequency of the node in MHz.
Once this information has been defined, the data for each node is 
output.

During the evaluation of NCS the following two programs were created 
and are included as examples:

Summary statistics is a simple C program which reads the QQ output file
and produces a summary report of the time spent in each state, the 
number of times each event or state, etc.

Profile viewer is a simple graphical application.  Data is read from the output
file, and piped to \code {gnuplot} for display.  A simple interface
allows the user to select which nodes, events, and time ranges are
displayed.


\section  {Examples}

Example of what needs to be included in the source (how to define what 
is to be monitored)
Example of what is output by QQ(how is the measurement recorded)
Example of how to produce graphical output (what can you see) - maybe 
a listing of what can be visualized via the output file(s).

Sequential Profiling



Parallel Profiling


Figure \ref{fig:qqplt1} shows an example of such a tool: several timesteps of
an NCS run are shown, with the times spent in various sections of the code.


\begin{figure}[!h]
    \includegraphics[width=1.0\textwidth, height=0.5\textwidth]{qqplt1.eps}
  \caption{Plot of Typical QQ Output. \label{fig:qqplt1}}
\end{figure}


\section {Conclusions and Future Work}

Conclusions
QQ has proven to be a valuable set of tools for the profiling of
various programs.  The temporal resolution allows for fine-grained
measurements of specific events or blocks of code.  It can be used on
sequential, distributed and parallel programs without modification.

Future Work
The incorporation of the various hardware implementations by using
different flags on the executable would extend the usability of these
tools.  Also, the ability to measure memory at an object or event level
with a small memory and perforamnce footprint, is an area that requires
additional work.  





