-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 I''ve done some google searches but haven''t found an example script for how to record the amount of CPU time used by a process. I''m trying to profile a build system by tracing how many and what kinds of processes are started. I want to record the following information about every process within a process tree: real start time real end time CPU time used working directory executable command line (argv) Collecting the real start time/end time/cwd/exectable is fairly simple, I think I''ve got it. I was thinking that CPU time could be calculated by using vtimestamp: collect the vtimestamp at the start and the end of each LWP, and total them to get the CPU time for the process. However, I''m having trouble with the proc:::lwp-start probe: it seems to fire in the context of the parent process, not in the context of the new thread that''s starting: bsmedberg $ sudo dtrace -s ../process-tree.d -q 32254 proc:::lwp-start pid: 32254 tid: 111341864 vtimestamp: 96036509 proc:::create pid: 32254 args[0]->pr_pid: 43113 proc:::lwp-create pid: 32254 tid: 111341864 args[1]->pr_pid: 73060628 args[0]->pr_lwpid: 74125832 vtimestamp: 95792715 proc:::exec-success pid: 43113 ppid: 32254 cwd: obj curpsinfo->pr_fname: cat proc:::exit pid: 43113 proc:::lwp-exit pid: 43113 tid: 74125832 vtimestamp: 3361917 This means I can''t simply use lwp-start and lwp-exit and do vtimestamp math, because the vtimestamp of the lwp-create probe is the vtimestamp of the shell thread, not the new thread! Does anyone have an example script or suggestion how to record the amount of CPU time a process uses? Note: This is MacOS. - --BDS -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.5 (Darwin) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFJIZ5WSSwGp5sTYNkRAhlnAJ9hMuv00eCD6DSWYFy8BMNPHxTGqgCg4nLa y3C4zIILmCKS/SFoxjZdUX4=R4OP -----END PGP SIGNATURE-----
The system tracks this for you. Why not use that? Look at procpsinfo and lwpsinfo which DTrace makes available. man -s 4 proc describes the contents of these as well as others. Jim --- Benjamin Smedberg wrote:> -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA1 > > I''ve done some google searches but haven''t found an example script for how > to record the amount of CPU time used by a process. > > I''m trying to profile a build system by tracing how many and what kinds of > processes are started. I want to record the following information about > every process within a process tree: > > real start time > real end time > CPU time used > working directory > executable > command line (argv) > > Collecting the real start time/end time/cwd/exectable is fairly simple, I > think I''ve got it. > > I was thinking that CPU time could be calculated by using vtimestamp: > > collect the vtimestamp at the start and the end of each LWP, and total them > to get the CPU time for the process. However, I''m having trouble with the > proc:::lwp-start probe: it seems to fire in the context of the parent > process, not in the context of the new thread that''s starting: > > bsmedberg $ sudo dtrace -s ../process-tree.d -q 32254 > proc:::lwp-start > pid: 32254 > tid: 111341864 > vtimestamp: 96036509 > proc:::create > pid: 32254 > args[0]->pr_pid: 43113 > proc:::lwp-create > pid: 32254 > tid: 111341864 > args[1]->pr_pid: 73060628 > args[0]->pr_lwpid: 74125832 > vtimestamp: 95792715 > proc:::exec-success > pid: 43113 > ppid: 32254 > cwd: obj > curpsinfo->pr_fname: cat > proc:::exit > pid: 43113 > proc:::lwp-exit > pid: 43113 > tid: 74125832 > vtimestamp: 3361917 > > This means I can''t simply use lwp-start and lwp-exit and do vtimestamp math, > because the vtimestamp of the lwp-create probe is the vtimestamp of the > shell thread, not the new thread! > > Does anyone have an example script or suggestion how to record the amount of > CPU time a process uses? > > Note: This is MacOS. > > - --BDS > -----BEGIN PGP SIGNATURE----- > Version: GnuPG v1.4.5 (Darwin) > Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org > > iD8DBQFJIZ5WSSwGp5sTYNkRAhlnAJ9hMuv00eCD6DSWYFy8BMNPHxTGqgCg4nLa > y3C4zIILmCKS/SFoxjZdUX4> =R4OP > -----END PGP SIGNATURE----- > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org > >
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 James Litchfield wrote:> The system tracks this for you. Why not use that? Look at procpsinfo > and lwpsinfo which DTrace makes available. man -s 4 proc describes the > contents of these as well as others.Looking at http://docs.sun.com/app/docs/doc/817-6223/chp-proc-psinfo?a=view and http://docs.sun.com/app/docs/doc/817-6223/chp-proc-lwpsinfo?a=view I don''t see any information about CPU time. According to the man pages, there is a member psinfo.pr_time, but this is of type timestruc_t which is not reflected into dtrace (experiments confirm that I can''t use this member directly): http://docs.sun.com/app/docs/doc/816-5174/proc-4?a=view Is there some way to use the timestruc_t type indirectly? - --BDS -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.5 (Darwin) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFJIbbtSSwGp5sTYNkRAsIHAKC+n5xOfyJ7GfMBZB+CIsUy0EK+HgCeOmOf NZscEznLHopwuRYAAfbLPHY=yWa8 -----END PGP SIGNATURE-----
On Mon, Nov 17, 2008 at 11:39:51AM -0500, Benjamin Smedberg wrote:> -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA1 > > I''ve done some google searches but haven''t found an example script for how > to record the amount of CPU time used by a process. > > I''m trying to profile a build system by tracing how many and what kinds of > processes are started. I want to record the following information about > every process within a process tree: > > real start time > real end time > CPU time used > working directory > executable > command line (argv) > > Collecting the real start time/end time/cwd/exectable is fairly simple, I > think I''ve got it. > > I was thinking that CPU time could be calculated by using vtimestamp: > > collect the vtimestamp at the start and the end of each LWP, and total them > to get the CPU time for the process. However, I''m having trouble with the > proc:::lwp-start probe: it seems to fire in the context of the parent > process, not in the context of the new thread that''s starting: > > bsmedberg $ sudo dtrace -s ../process-tree.d -q 32254 > proc:::lwp-start > pid: 32254 > tid: 111341864 > vtimestamp: 96036509 > proc:::create > pid: 32254 > args[0]->pr_pid: 43113 > proc:::lwp-create^^^^^^^^^^ lwp-create is fired from the creating thread. lwp-start is fired from the new thread.> pid: 32254 > tid: 111341864 > args[1]->pr_pid: 73060628 > args[0]->pr_lwpid: 74125832 > vtimestamp: 95792715> proc:::exec-success > pid: 43113 > ppid: 32254 > cwd: obj > curpsinfo->pr_fname: cat > proc:::exit > pid: 43113 > proc:::lwp-exit > pid: 43113 > tid: 74125832 > vtimestamp: 3361917 > > This means I can''t simply use lwp-start and lwp-exit and do vtimestamp math, > because the vtimestamp of the lwp-create probe is the vtimestamp of the > shell thread, not the new thread! > > Does anyone have an example script or suggestion how to record the amount of > CPU time a process uses? > > Note: This is MacOS. > > - --BDS > -----BEGIN PGP SIGNATURE----- > Version: GnuPG v1.4.5 (Darwin) > Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org > > iD8DBQFJIZ5WSSwGp5sTYNkRAhlnAJ9hMuv00eCD6DSWYFy8BMNPHxTGqgCg4nLa > y3C4zIILmCKS/SFoxjZdUX4> =R4OP > -----END PGP SIGNATURE----- > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org
On Mon, Nov 17, 2008 at 09:26:20AM -0800, James Litchfield wrote:> The system tracks this for you. Why not use that? Look at procpsinfo > and lwpsinfo which DTrace makes available. man -s 4 proc describes the > contents of these as well as others.Or you could enable extended accounting and use accounting records. Cheers, - jonathan> --- > > Benjamin Smedberg wrote: > > -----BEGIN PGP SIGNED MESSAGE----- > > Hash: SHA1 > > > > I''ve done some google searches but haven''t found an example script for how > > to record the amount of CPU time used by a process. > > > > I''m trying to profile a build system by tracing how many and what kinds of > > processes are started. I want to record the following information about > > every process within a process tree: > > > > real start time > > real end time > > CPU time used > > working directory > > executable > > command line (argv) > > > > Collecting the real start time/end time/cwd/exectable is fairly simple, I > > think I''ve got it. > > > > I was thinking that CPU time could be calculated by using vtimestamp: > > > > collect the vtimestamp at the start and the end of each LWP, and total them > > to get the CPU time for the process. However, I''m having trouble with the > > proc:::lwp-start probe: it seems to fire in the context of the parent > > process, not in the context of the new thread that''s starting: > > > > bsmedberg $ sudo dtrace -s ../process-tree.d -q 32254 > > proc:::lwp-start > > pid: 32254 > > tid: 111341864 > > vtimestamp: 96036509 > > proc:::create > > pid: 32254 > > args[0]->pr_pid: 43113 > > proc:::lwp-create > > pid: 32254 > > tid: 111341864 > > args[1]->pr_pid: 73060628 > > args[0]->pr_lwpid: 74125832 > > vtimestamp: 95792715 > > proc:::exec-success > > pid: 43113 > > ppid: 32254 > > cwd: obj > > curpsinfo->pr_fname: cat > > proc:::exit > > pid: 43113 > > proc:::lwp-exit > > pid: 43113 > > tid: 74125832 > > vtimestamp: 3361917 > > > > This means I can''t simply use lwp-start and lwp-exit and do vtimestamp math, > > because the vtimestamp of the lwp-create probe is the vtimestamp of the > > shell thread, not the new thread! > > > > Does anyone have an example script or suggestion how to record the amount of > > CPU time a process uses? > > > > Note: This is MacOS. > > > > - --BDS > > -----BEGIN PGP SIGNATURE----- > > Version: GnuPG v1.4.5 (Darwin) > > Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org > > > > iD8DBQFJIZ5WSSwGp5sTYNkRAhlnAJ9hMuv00eCD6DSWYFy8BMNPHxTGqgCg4nLa > > y3C4zIILmCKS/SFoxjZdUX4> > =R4OP > > -----END PGP SIGNATURE----- > > _______________________________________________ > > dtrace-discuss mailing list > > dtrace-discuss at opensolaris.org > > > > > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Jonathan Adams wrote:>> lwp-create is fired from the creating thread. lwp-start is fired from the >> new thread.But this is demonstrably not true, at least on MacOS: lwp-start and lwp-create both fired with> pid: 32254 > tid: 111341864but lwp-exit fired with> pid: 43113 > tid: 74125832I''m going to run this same experiment in OpenSolaris to see if this is just a bug in the MacOS implementation. - --BDS -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.5 (Darwin) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFJId3uSSwGp5sTYNkRAiXvAJ9bYCSiLCdYviGCiNZq3f0A0V9smwCfccec diR479nYnSbyHtFw47LWBoI=lm0c -----END PGP SIGNATURE-----
On Mon, Nov 17, 2008 at 04:11:10PM -0500, Benjamin Smedberg wrote:> -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA1 > > Jonathan Adams wrote: > > >> lwp-create is fired from the creating thread. lwp-start is fired from the > >> new thread. > > But this is demonstrably not true, at least on MacOS: > > lwp-start and lwp-create both fired with > > > pid: 32254 > > tid: 111341864 > > but lwp-exit fired with > > pid: 43113 > > tid: 74125832 > > I''m going to run this same experiment in OpenSolaris to see if this is just > a bug in the MacOS implementation.This sounds like a bug in the MacOS implementation; from the Dynamic Tracing Guide: http://docs.sun.com/app/docs/doc/817-6223/6mlkidloj?l=en&a=view ... lwp-create Probe that fires when an LWP is created, typically as a result of thr_create(3C). The lwpsinfo_t corresponding to the new thread is pointed to by args[0]. The psinfo_t of the process containing the thread is pointed to by args[1]. lwp-start Probe that fires within the context of a newly created LWP. The lwp-start probe will fire before any user-level instructions are executed. If the LWP is the first LWP in the process, the start probe will fire, followed by lwp-start. ... Cheers, - jonathan
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Jonathan Adams wrote:> This sounds like a bug in the MacOS implementation; from the Dynamic Tracing > Guide: > > http://docs.sun.com/app/docs/doc/817-6223/6mlkidloj?l=en&a=view > ... > lwp-create > > Probe that fires when an LWP is created, typically as a result of > thr_create(3C). The lwpsinfo_t corresponding to the new thread is > pointed to by args[0]. The psinfo_t of the process containing the > thread is pointed to by args[1].I''ve verified that the Solaris implementation is correct, and the MacOS isn''t. Does anyone know the correct place to report bugs in the MacOS implementation of DTrace? - --BDS -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.5 (Darwin) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFJJIH4SSwGp5sTYNkRAoX0AKCAmwm2eN1x8kQQDHWmG9Ep4W9shgCfRhY2 Prg4RYtmWx7nKN5l2ZFgpp4=oO2k -----END PGP SIGNATURE-----
On Nov 19, 2008, at 1:15 PM, Benjamin Smedberg wrote:> -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA1 > > Jonathan Adams wrote: > >> This sounds like a bug in the MacOS implementation; from the >> Dynamic Tracing >> Guide: >> >> http://docs.sun.com/app/docs/doc/817-6223/6mlkidloj?l=en&a=view >> ... >> lwp-create >> >> Probe that fires when an LWP is created, typically as a result of >> thr_create(3C). The lwpsinfo_t corresponding to the new thread is >> pointed to by args[0]. The psinfo_t of the process containing the >> thread is pointed to by args[1]. > > I''ve verified that the Solaris implementation is correct, and the > MacOS > isn''t. Does anyone know the correct place to report bugs in the MacOS > implementation of DTrace?Definitely a bug, we''re looking at it now. James M