This is the mail archive of the
cygwin@cygwin.com
mailing list for the Cygwin project.
Re: Is multithreaded profiling on cygwin possible?
- From: "peter garrone" <pgarrone at linuxmail dot org>
- To: cygwin at cygwin dot com
- Date: Tue, 21 Oct 2003 07:40:49 +0800
- Subject: Re: Is multithreaded profiling on cygwin possible?
>Even if no one else comments, I really appreciate all this work you're
>doing! Also, thanks for continuing to send me the updated patches. I
>wish I had more time to look over them in detail right now. I'll try and
>do that soon. I assume it is ok to give an open invitation for anyone
>else who would like to give the a whirl?
>
>BTW, if you are interested in contributing this, please take a look at the
>"Before you get started" section of http://cygwin.com/contrib.html since
>the assignment process can take some time.
>
>Again, great work from my point of view!
>
>--
>Brian Ford
>Senior Realtime Software Engineer
>VITAL - Visual Simulation Systems
>FlightSafety International
>Phone: 314-551-8460
>Fax: 314-551-8444
>
Thanks Brian.
This message, I believe, gives the code upon which Brian's endorsement is based.
Regarding the IP issues, there is no problem with my posting the code to the group,
or with anyone using it, from my employers point of view. No warranty is implied etc.
I have forwarded the small document that our legal people need to sign.
Until then I would imagine that the code cannot be part of cygwin.
This message contains the code for two files, profil.c, and gmraw.c.
To use this code, replace winsup/cygwin/profil.c with the file profil.c here.
Recompile cygwin. Either update the DLL, or directly link in the profil.o object file.
- Compile and link with -pg.
- If using multi-threaded code, each new thread needs to call "moncontrol(1)"
upon creation. The main thread calls it automatically.
- To profile DLL's, and general memory ranges,
set the environment variable PROFILE_RANGE. This variable
should consist of one or more colon separated entries. Each entry consists
of a name, followed by optional comma separated fields representing
the scale, offset, and size, in hex.
It the name is the name of a DLL, then the entry is a DLL entry, else a general memory range.
The scale field determines the profiling resolution. Divide 0x10000 by the scale
value to give the profiling resolution in bytes. For a DLL, the default scale is
10000 giving a resolution of 1 byte. For a memory range, the default scale is such as to
give 256 incrementing counters, or a scale of 1 if the range is too great for that.
If the name is the name of a DLL, then the offset is with respect to the loaded DLL,
otherwise it is a fixed address. The default offset value is zero.
The size field defines the size of the address range to be profiled. If the range
covers a DLL, then the default value is the size of the DLL less the offset. If
the range is a general memory range, the default size is 0x80000000.
I use the following to profile all the DLL's my application links to, the
entire memory range from 0 to 0x80000000 (called "general"), and a small area where my application
is spending a lot of CPU (called "busy"). The list of DLL's was obtained using cygcheck.
export PROFILE_RANGE='general:busy,10000,7ffe0000,10000:cygX11-6.dll:cygcygipc-2.dll:cygwin1.dll:KERNEL32.dll:ntdll.dll:GDI32.dll:USER32.dll:ADVAPI32.dll:RPCRT4.dll:GLU32.DLL:msvcrt.dll:OPENGL32.dll:DDRAW.dll:DCIMAN32.dll:glut32.dll:WINMM.dll'
Alternatively, the following command causes only the cygwin dll to be profiled.
export PROFILE_RANGE='cygwin1.dll'
- Execute your program.
Upon program termination, besides gmon.out,
a file in gmon.out format will be output for each range, with ".gmonout" appended
to the name of each range, cygwin1.dll.gmonout etc.
To profile the cygwin dll, provided you are using an unstripped dll, the command
gprof /bin/cygwin1.dll cygwin1.dll.gmonout
produces a flat profile.
To see a memory range, or for dlls with no symbolic information, a utility called gmraw is provided.
Compile this with "gcc gmraw.c -o gmraw".
The command "gmraw -f general.gmonout" for example provides information about that particular range.
- WRT the interface. Calling moncontrol(0) at any point should terminate the profiling thread,
and profiling of the memory ranges, but the data should still be saved upon program termination.
It should be possible to use the "profil" function provided "-pg" compilation/linkage option
is not used. Each thread should call "profil" with identical parameters. I have not tested
this much.
-----------------------------------------------------------------------------------------
File profil.c
-----------------------------------------------------------------------------------------
/* profil.c -- win32 profil.c equivalent
Copyright 1998, 1999, 2000, 2001 Red Hat, Inc.
This file is part of Cygwin.
This software is a copyrighted work licensed under the terms of the
Cygwin license. Please consult the file "CYGWIN_LICENSE" for
details. */
#include <windows.h>
#include <psapi.h>
#include <stdio.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <unistd.h>
#include <fcntl.h>
#include <errno.h>
#include <math.h>
#include <profil.h>
#include <gmon.h>
#include <assert.h>
#define SLEEPTIME (1000 / PROF_HZ)
#define MAXTHREADS 256
/**
* This is a per-thread structure that the profiling thread
* uses to track the profiled threads in the system.
*/
struct wthread
{
struct wthread *next;
HANDLE handle;
long long last_cpu_time;
};
static struct wthread *get_wthread_entry (void);
/**
* This structure is for tracking a profiling range context.
*/
struct profile_range_entry
{
struct profile_range_entry *next;
char *name;
unsigned long scale;
unsigned long offset;
unsigned long range;
unsigned long base_address;
unsigned long counter_size;
int ticks;
struct profinfo prof;
};
static struct wthread wthreads[MAXTHREADS], *wthread_free_list, *wthread_list;
static int wthread_count;
static DWORD wthread_tls_index;
static HANDLE prof_mutex;
static struct profile_range_entry *profile_range_list;
static int total_profile_ticks;
static int total_unallocated_ticks;
static int total_normal_ticks;
static unsigned long unalloc_lowpc;
static unsigned long unalloc_highpc;
static _WINHANDLE profthr; //only one process profiling thread
/* global profinfo for profil() call */
static struct profinfo prof;
/**
* GetModuleInformation does not appear to get linked
* in by default. Rather then changing the compiler specs,
* load up the dll. Perhaps this is lazy.
*/
static FARPROC p_GetModuleInformation;
/**
* Save data file for use by gprof.
*/
static void
save_gmon_file (char *name, struct profinfo *p, int datasize)
{
int fd;
struct gmonhdr gmonhdr, *hdr;
char proffile[128];
snprintf (proffile, sizeof (proffile), "%s.gmonout", name);
fd = open (proffile, O_CREAT | O_TRUNC | O_WRONLY | O_BINARY, 0666);
if (fd < 0)
{
perror (proffile);
return;
}
memset (&gmonhdr, 0, sizeof (gmonhdr));
hdr = (struct gmonhdr *) &gmonhdr;
hdr->lpc = p->lowpc;
hdr->hpc = p->highpc;
hdr->ncnt = datasize + sizeof (gmonhdr);
hdr->version = GMONVERSION;
hdr->profrate = PROF_HZ;
write (fd, (char *) hdr, sizeof *hdr);
write (fd, p->counter, datasize);
close (fd);
}
/*
* Given profiler ticks, convert to a string representation.
* This function returns a pointer to a static array.
* It should not be used in a multi-threading context,
* not should it appear more then once in a printf argument list.
*/
static char *
ticktime (unsigned ticks)
{
static char buff[32];
snprintf (buff, sizeof (buff), "%u.%02u seconds", ticks / PROF_HZ,
((ticks % PROF_HZ) * 100) / PROF_HZ);
return buff;
}
static void
dump_profile_range_entries (void)
{
struct profile_range_entry *pd;
printf ("Profile range entry dump\n");
printf ("Total cpu time allocated to static code (%lx -> %lx) %s\n",
prof.lowpc, prof.highpc, ticktime (total_normal_ticks));
for (pd = profile_range_list; pd != NULL; pd = pd->next)
{
int total = (((long long) pd->ticks) * 100) / PROF_HZ;
printf ("profile range %s ", pd->name);
printf (" (%lx -> %lx) ", pd->prof.lowpc, pd->prof.highpc);
printf (" %s\n", ticktime (total));
save_gmon_file (pd->name, &pd->prof, pd->counter_size);
}
printf ("Total cpu time accumulated by profiler %s\n",
ticktime (total_profile_ticks));
if (total_unallocated_ticks)
{
printf ("Total cpu time unallocated %s\n",
ticktime (total_unallocated_ticks));
printf ("Unallocated ticks PC range %lx to %lx\n", unalloc_lowpc,
unalloc_highpc);
}
}
/*
* one or more profile address ranges may be profiled.
* An environment variable PROFILE_RANGE is set
* to one or more colon separated entries.
* Each entry consists of a name,
* followed by optional comma separated fields scale, offset, range.
* The name is either a dll or simply a tag.
* The scale is as per profil call, but in hex.
* So a scale of 10000 gives unity.
* The offset is offset within the dll.
* The range is the size of the area to profile within the dll.
* If scale, offset, range are absent, scale is unity, offset and range cover whole dll.
* If range is absent, but scale and offset present, then goes to end of dll.
*/
static void
load_profile_range_entries (void)
{
static char *decode_profile_range_field (char *, unsigned long *);
char *penv = getenv ("PROFILE_RANGE");
if (!penv)
return;
while (*penv != 0)
{
struct profile_range_entry *pd;
char *p = penv;
char *p0;
int name_size;
HMODULE dll_handle;
MODULEINFO module_info;
BOOL rb;
u_long maxbin;
while (*penv != ':' && *penv)
penv++;
if (*penv)
penv++;
for (p0 = p; *p0 && *p0 != ',' && *p0 != ':'; p0++);
name_size = p0 - p;
pd =
(struct profile_range_entry *)
malloc (sizeof (struct profile_range_entry));
pd->name = (char *) malloc (name_size + 1);
strncpy (pd->name, p, name_size);
pd->name[name_size] = 0;
p = decode_profile_range_field (p, &pd->scale);
p = decode_profile_range_field (p, &pd->offset);
p = decode_profile_range_field (p, &pd->range);
//find the dll referred to.
dll_handle = LoadLibrary (pd->name);
if (dll_handle)
{
unsigned long dll_size;
unsigned long base_address;
//Get information
rb = p_GetModuleInformation (GetCurrentProcess (),
dll_handle,
&module_info, sizeof (module_info));
assert (rb);
base_address = (unsigned long) module_info.lpBaseOfDll;
dll_size = module_info.SizeOfImage;
if (pd->scale == 0)
pd->scale = 0x10000; //unity by default.
if (!pd->range)
pd->range = dll_size - pd->offset;
pd->offset += base_address;
}
else
{
//not a dll, but a general region
//want defaults for range, scale, offset
//leave offset of 0 if not set.
//let range be 0 to 80000000 if not set
if (!pd->range)
pd->range = 0x80000000 - pd->offset;
//if scale is not set, let it only be 256 entries. or 1 if not
if (!pd->scale)
{
pd->scale = PROFSCALE (pd->range, 256);
/* this gives 256 entries.
* But with max range, this could be insufficient.
*/
if (!pd->scale)
pd->scale = 1;
}
}
//absolute size of counter data.
pd->counter_size =
(sizeof (u_short)) * PROFIDX ((pd->range + pd->offset), pd->offset,
pd->scale);
pd->prof.lowpc = pd->offset;
pd->prof.counter = (u_short *) malloc (pd->counter_size);
maxbin = pd->counter_size >> 1;
pd->prof.highpc = PROFADDR (maxbin, pd->offset, pd->scale);
pd->prof.scale = pd->scale;
pd->ticks = 0;
pd->next = profile_range_list;
profile_range_list = pd;
}
atexit (dump_profile_range_entries);
}
static char *
decode_profile_range_field (char *p, unsigned long *field)
{
//at entry, p points to the prior field
//a pointer to the current field that is decoded is returned
//no more fields, return 0
int n;
*field = 0;
if (!p)
return NULL;
while (*p && *p != ':' && *p != ',')
p++;
if (*p != ',')
return 0;
p++;
if (!*p || *p == ',')
return 0;
n = sscanf (p, "%lx", field);
if (n)
return p;
else
return 0;
}
static void
create_mutex (void)
{
if (!prof_mutex)
{
HMODULE lpsapi = LoadLibrary ("psapi.dll");
assert (lpsapi != 0);
p_GetModuleInformation =
GetProcAddress (lpsapi, "GetModuleInformation");
wthread_tls_index = TlsAlloc ();
assert (wthread_tls_index != TLS_OUT_OF_INDEXES);
load_profile_range_entries ();
prof_mutex = CreateMutex (NULL, FALSE, NULL);
assert (prof_mutex);
}
}
static long long
get_total_thread_time (HANDLE thread_handle)
{
BOOL rb;
union
{
FILETIME f;
long long x;
}
creation_time, exit_time, kernel_time, user_time;
assert (sizeof (FILETIME) == sizeof (long long));
rb = GetThreadTimes (thread_handle,
&creation_time.f,
&exit_time.f, &kernel_time.f, &user_time.f);
assert (rb);
return kernel_time.x + user_time.x;
}
/*
* Assign a profiling tick.
* return true if assigned.
*/
static inline int
do_profile (struct profinfo *p, u_long pc, int ticks, int *pinc)
{
u_long idx;
if (!p->counter)
return 0;
if (pc >= p->lowpc && pc < p->highpc)
{
idx = PROFIDX (pc, p->lowpc, p->scale);
p->counter[idx] += ticks;
if (pinc)
*pinc += ticks;
return 1;
}
return 0;
}
/* Everytime we wake up use the main thread pc to hash into the cell in the
profile buffer ARG. */
static DWORD CALLBACK
profthr_func (LPVOID arg)
{
u_long pc;
int tick_base;
SetThreadPriority (profthr, THREAD_PRIORITY_TIME_CRITICAL);
WaitForSingleObject (prof_mutex, INFINITE);
/* work out how much the counters increment for a nominal profiling interrupt.
* Note that the actual interrupt is likely to be slower.
* According to msdn, the FILETIME is 100 nanosecond units
* So given PROF_HZ,
*/
tick_base = 10000000 / PROF_HZ;
for (;;)
{
struct wthread **wpp, *wp;
//suspend all threads
for (wp = wthread_list; wp != 0; wp = wp->next)
{
int res;
HANDLE handle = wp->handle;
res = SuspendThread (handle);
if (res == -1)
wp->handle = 0; //thread finished, mark it for later collection.
}
/* grab any free containers. */
for (wpp = &wthread_list; *wpp != 0; wpp = &((*wpp)->next))
{
while (*wpp && (*wpp)->handle == 0)
{
struct wthread *wp = *wpp;
*wpp = wp->next;
wp->last_cpu_time = 0;
wp->next = wthread_free_list;
wthread_free_list = wp;
}
if (*wpp == 0)
break;
}
//get the time for all threads
//do the profiling for any thread that consumed cpu
for (wp = wthread_list; wp != 0; wp = wp->next)
{
BOOL rb;
CONTEXT ctx;
int ticks;
int allocated_f = 0;
long long total_thread_time;
struct profile_range_entry *pd;
int tick_time;
total_thread_time = get_total_thread_time (wp->handle);
tick_time = (int) (total_thread_time - wp->last_cpu_time);
assert (tick_time >= 0);
ticks = tick_time / tick_base;
if (ticks == 0)
continue;
total_profile_ticks += ticks;
wp->last_cpu_time += tick_base * ticks;
/* At least one, and if all goes to plan, only one, tick to assign.
* However if this thread was delayed, there could be more.
*/
//getting the PC is the most time consuming part of the whole thing,
//so only do it if necessary
memset (&ctx, 0, sizeof ctx);
ctx.ContextFlags = CONTEXT_CONTROL | CONTEXT_INTEGER;
rb = GetThreadContext (wp->handle, &ctx);
assert (rb);
pc = ctx.Eip;
assert (pc != 0);
allocated_f += do_profile (&prof, pc, ticks, &total_normal_ticks); // for -pg
for (pd = profile_range_list; pd != 0; pd = pd->next)
{
allocated_f += do_profile (&pd->prof, pc, ticks, &pd->ticks); // for PROFILE_RANGEs
}
if (!allocated_f)
{
total_unallocated_ticks++;
if (!unalloc_lowpc)
{
unalloc_lowpc = pc;
unalloc_highpc = pc;
}
else if (pc < unalloc_lowpc)
unalloc_lowpc = pc;
else if (pc > unalloc_highpc)
unalloc_highpc = pc;
}
}
//resume all threads
for (wp = wthread_list; wp != 0; wp = wp->next)
{
assert (wp->handle);
ResumeThread (wp->handle);
}
ReleaseMutex (prof_mutex);
Sleep (SLEEPTIME);
WaitForSingleObject (prof_mutex, INFINITE);
}
return 0;
}
/* This either retrieves the wthread for this thread,
* or allocates and stores one.
* Note that any thread that makes a dll call
* will get a structure.
*/
static struct wthread *
get_wthread_entry (void)
{
struct wthread *wp;
int r;
wp = (struct wthread *) TlsGetValue (wthread_tls_index);
if (wp)
return wp;
/* no entry exists. Have to allocate one. */
WaitForSingleObject (prof_mutex, INFINITE);
/* see if any structures on the free list. */
if (wthread_free_list)
{
wp = wthread_free_list;
wthread_free_list = wp->next;
}
else
{
assert (wthread_count < MAXTHREADS);
wp = &wthreads[wthread_count++];
}
/* get handle for this thread */
{
HANDLE current_process;
HANDLE current_thread;
current_process = GetCurrentProcess ();
current_thread = GetCurrentThread ();
r = DuplicateHandle (current_process, current_thread, current_process,
&wp->handle, 0, FALSE, DUPLICATE_SAME_ACCESS);
assert (r);
}
/* initialise the last cpu time, so profiling start is this point. */
wp->last_cpu_time = get_total_thread_time (wp->handle);
wp->next = wthread_list;
wthread_list = wp;
r = TlsSetValue (wthread_tls_index, wp);
assert (r);
ReleaseMutex (prof_mutex);
return wp;
}
/* Stop profiling to the profiling buffer pointed to by P. */
static int
profile_off (void)
{
create_mutex ();
WaitForSingleObject (prof_mutex, INFINITE);
if (profthr)
{
TerminateThread (profthr, 0);
CloseHandle (profthr);
profthr = 0;
}
ReleaseMutex (prof_mutex);
return 0;
}
/*
* start or stop profiling
*
* profiling goes into the SAMPLES buffer of size SIZE (which is treated
* as an array of u_shorts of size size/2)
*
* each bin represents a range of pc addresses from OFFSET. The number
* of pc addresses in a bin depends on SCALE. (A scale of 65536 maps
* each bin to two addresses, A scale of 32768 maps each bin to 4 addresses,
* a scale of 1 maps each bin to 128k addreses). Scale may be 1 - 65536,
* or zero to turn off profiling
*
*/
int
profile_ctl (struct profinfo *p, char *samples, size_t size,
u_long offset, u_int scale)
{
int r = 0;
u_long maxbin;
create_mutex ();
get_wthread_entry (); //ensure this thread is added to internal list
WaitForSingleObject (prof_mutex, INFINITE);
if (samples == NULL)
{
p->counter = 0;
}
else
{
maxbin = size >> 1;
p->counter = (u_short *) samples;
p->lowpc = offset;
p->highpc = PROFADDR (maxbin, offset, scale);
p->scale = scale;
/* Create a timer thread and pass it a pointer P to the profiling buffer. */
if (!profthr)
profthr = CreateThread (0, 0, profthr_func, 0, 0, NULL);
if (!profthr)
{
errno = EAGAIN;
r = -1;
}
}
ReleaseMutex (prof_mutex);
return r;
}
/* Equivalent to unix profil()
Every SLEEPTIME interval, the user's program counter (PC) is examined:
offset is subtracted and the result is multiplied by scale.
This function needs to be called for every thread that is profiled.
When it is called with null arguments, profiling ceases.
*/
int
profil (char *samples, size_t size, u_long offset, u_int scale)
{
int r;
r = profile_ctl (&prof, samples, size, offset, scale);
if (samples == 0)
{
profile_off ();
}
return r;
}
-----------------------------------------------------------------------------------------
File gmraw.c
-----------------------------------------------------------------------------------------
/* Simple program to dump gmon time data */
#include <stdio.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <stdlib.h>
#include <string.h>
#define ENTRIES_PER_LINE 8
#define trace printf("line %d\n",__LINE__)
void usage(char * str)
{
fprintf(stderr,"%s\n",str);
fprintf(stderr,"Usage\n");
fprintf(stderr," -f gmonfile Specify input file\n");
exit(-1);
}
struct gmonhdr {
u_long lpc; /* base pc address of sample buffer */
u_long hpc; /* max pc address of sampled buffer */
int ncnt; /* size of sample buffer (plus this header) */
int version; /* version number */
int profrate; /* profiling clock rate */
int spare[3]; /* reserved */
};
void xerror(char * str)
{
fprintf(stderr,"error %s\n",str);
exit(-1);
}
static char * format_time(int val, int profhz)
{
static char buff[32];
snprintf(buff,sizeof(buff),"%3d.%02d", val/profhz, ((val%profhz)*100)/profhz);
return buff;
}
void output_sep(void)
{
int i;
for(i=0;i<ENTRIES_PER_LINE*7 + 10;i++)printf("-");
printf("\n");
}
void dump(char * fname)
{
int fd;
int r;
struct gmonhdr gmonhdr, *hdr;
int nitems;
int nlines;
int linesize;
int i;
int entry_width;
unsigned long file_total = 0;
unsigned short * linebuff;
fd = open(fname,O_RDONLY);
if(fd < 0)
{
fprintf(stderr,"Cant open %s\n",fname);
exit(-1);
}
r = read(fd,&gmonhdr,sizeof(gmonhdr));
if(r != sizeof(gmonhdr))xerror("file read error");
hdr = &gmonhdr;
nitems = (hdr->ncnt - sizeof(gmonhdr))/sizeof(short);
if(hdr->hpc < hdr->lpc)xerror("file data error, hpc < lpc");
entry_width = (hdr->hpc - hdr->lpc)/nitems;
printf("Data from %lx to %lx, profile rate %d Hertz, covering 0x%x bytes per entry\n",
hdr->lpc, hdr->hpc, hdr->profrate, entry_width);
nlines = nitems/ENTRIES_PER_LINE;
linesize = ENTRIES_PER_LINE*sizeof(short);
linebuff = (unsigned short *)malloc(linesize);
printf(" Address ");
for(i=0;i<ENTRIES_PER_LINE;i++)
{
printf(" %6x",i*entry_width);
}
printf(" Line Total\n");
output_sep();
for(i=0;i<nlines;i++)
{
int nr;
int j;
int total = 0;
unsigned long addr = hdr->lpc + i*ENTRIES_PER_LINE*entry_width;
unsigned short val;
nr = read(fd, linebuff, linesize);
if(nr < 0)xerror("file read error");
for(j=0;j<ENTRIES_PER_LINE;j++)
{
total += linebuff[j];
}
if(total == 0)continue;
printf("%08lx:",addr);
for(j=0;j<ENTRIES_PER_LINE;j++)
{
val = linebuff[j];
printf(" %s",format_time(val, hdr->profrate));
}
printf(" %s",format_time(total, hdr->profrate));
printf("\n");
file_total += total;
}
close(fd);
output_sep();
printf("File total %s seconds.\n",format_time(file_total, hdr->profrate));
free(linebuff);
}
int main(int argc, char ** argv)
{
int i;
char * fname = "gmon.out";
if(argc <= 1)usage("No arguments");
for(i=1;i<argc;i++)
{
if(!strcmp(argv[i],"-f"))
fname = argv[++i];
else usage("unknown argument");
}
dump(fname);
return 0;
}
-----------------------------------------------------------------------------------------
--
______________________________________________
Check out the latest SMS services @ http://www.linuxmail.org
This allows you to send and receive SMS through your mailbox.
Powered by Outblaze
--
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
Problem reports: http://cygwin.com/problems.html
Documentation: http://cygwin.com/docs.html
FAQ: http://cygwin.com/faq/