Skip site navigation (1)Skip section navigation (2) 
Date:      Mon, 14 Dec 2009 10:24:16 GMT
From:      Andrei Lavreniyuk <andy.lavr@reactor-xg.kiev.ua>
To:        freebsd-gnats-submit@FreeBSD.org
Subject:   misc/141452: DTrace stops tracing because of struct thread
Message-ID:  <200912141024.nBEAOGOD032938@www.freebsd.org>
Resent-Message-ID: <200912141030.nBEAU1XD034600@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help 

>Number:         141452
>Category:       misc
>Synopsis:       DTrace stops tracing because of struct thread
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Mon Dec 14 10:30:00 UTC 2009
>Closed-Date:
>Last-Modified:
>Originator:     Andrei Lavreniyuk
>Release:        FreeBSD 8.0-STABLE
>Organization:
Technica-03, Inc.
>Environment:
FreeBSD datacenter.technica-03.local 8.0-STABLE FreeBSD 8.0-STABLE #0: Sat Dec 12 21:41:15 EET 2009     root@datacenter.technica-03.local:/usr/obj/usr/src/sys/SMP64  amd64
>Description:

DTrace support was enabled referring to http://www.freebsd.org/doc/en_US.ISO8859-1/books/handbook/dtrace-enable.html

However, various DTraceToolkit applications stop tracing as follows.


# dtrace -l | wc -l
   28647           
# ./hotkernel      
Sampling... Hit Ctrl-C to end.
dtrace: invalid probe specifier 
        #pragma D option quiet  
        profile:::profile-1001hz
        /arg0/                  
        {                       
                @pc[arg0] = count();
        }                           
        dtrace:::END                
        {                           
                printa("%a %@d\n", @pc);
        }                               
: "/usr/lib/dtrace/psinfo.d", line 88: failed to resolve type kernel`struct thread * for identifier curthread: Unknown type name

FUNCTION                                                COUNT   PCNT
# ./procsystime -n ksh                                              
dtrace: invalid probe specifier                                     
 #pragma D option quiet                                             

 /*
  * Command line arguments
  */                      
 inline int OPT_elapsed  = 1;
 inline int OPT_cpu      = 0;
 inline int OPT_counts   = 0;
 inline int OPT_filter   = 1;
 inline int OPT_pid      = 0;
 inline int OPT_name     = 1;
 inline int OPT_totals   = 0;
 inline int OPT_command  = 0;
 inline int PID          = 0;
 inline string NAME      = "ksh";
 inline string COMMAND   = "";   

 dtrace:::BEGIN 
 {              
        self->start = 0;
        self->vstart = 0;
 }                       
 dtrace:::BEGIN          
 /! OPT_command/         
 {                       
        printf("Tracing... Hit Ctrl-C to end...\n");
 }                                                  

 /*
  * Set start timestamp and counts
  */                              
 syscall:::entry                  
 /(! OPT_filter) ||               
  (OPT_pid && pid == PID) ||      
  (OPT_name && execname == NAME) ||
  (OPT_command && pid == $target)/ 
 {                                 
        self->ok = 1;              
 }                                 
 syscall:::entry                   
 /self->ok/                        
 {                                 
        OPT_counts ? @Counts[probefunc] = count() : 1;
        (OPT_counts && OPT_totals) ? @Counts["TOTAL:"] = count() : 1;
        OPT_elapsed ? self->start = timestamp : 1;                   
        OPT_cpu ? self->vstart = vtimestamp : 1;                     
        self->ok = 0;                                                
 }                                                                   

 /*
  * Calculate time deltas
  */
 syscall:::return
 /self->start/
 {
        this->elapsed = timestamp - self->start;
        @Elapsed[probefunc] = sum(this->elapsed);
        OPT_totals ? @Elapsed["TOTAL:"] = sum(this->elapsed) : 1;
        self->start = 0;
 }
 syscall:::return
 /self->vstart/
 {
        this->cpu = vtimestamp - self->vstart;
        @CPU[probefunc] = sum(this->cpu);
        OPT_totals ? @CPU["TOTAL:"] = sum(this->cpu) : 1;
        self->vstart = 0;
 }

 /*
  * Elapsed time report
  */
 dtrace:::END
 /OPT_elapsed/
 {
        printf("\nElapsed Times for ");
        OPT_pid ? printf("PID %d,\n\n",PID) : 1;
        OPT_name ? printf("processes %s,\n\n",NAME) : 1;
        OPT_command ? printf("command %s,\n\n",COMMAND) : 1;
        (! OPT_filter) ? printf("all processes,\n\n") : 1;
        printf("%16s %18s\n","SYSCALL","TIME (ns)");
        printa("%16s %@18d\n",@Elapsed);
 }

 /*
  * CPU time report
  */
 dtrace:::END
 /OPT_cpu/
 {
        printf("\nCPU Times for ");
        OPT_pid ? printf("PID %d,\n\n",PID) : 1;
        OPT_name ? printf("processes %s,\n\n",NAME) : 1;
        OPT_command ? printf("command %s,\n\n",COMMAND) : 1;
        (! OPT_filter) ? printf("all processes,\n\n") : 1;
        printf("%16s %18s\n","SYSCALL","TIME (ns)");
        printa("%16s %@18d\n",@CPU);
 }

 /*
  * Syscall count report
  */
 dtrace:::END
 /OPT_counts/
 {
        printf("\nSyscall Counts for ");
        OPT_pid ? printf("PID %d,\n\n",PID) : 1;
        OPT_name ? printf("processes %s,\n\n",NAME) : 1;
        OPT_command ? printf("command %s,\n\n",COMMAND) : 1;
        (! OPT_filter) ? printf("all processes,\n\n") : 1;
        printf("%16s %18s\n","SYSCALL","COUNT");
        OPT_counts ? printa("%16s %@18d\n",@Counts) : 1;
 }
: "/usr/lib/dtrace/psinfo.d", line 88: failed to resolve type kernel`struct thread * for identifier curthread: Unknown type name


# cd Proc                                 
# ./dapptrace /bin/pwd                    
/root/DTraceToolkit/Proc                  
dtrace: invalid probe specifier           
 #pragma D option quiet                   

 /*
  * Command line arguments
  */                      
 inline int OPT_command   = 1;
 inline int OPT_liball    = 0;
 inline int OPT_indent    = 0;
 inline int OPT_printid   = 0;
 inline int OPT_relative  = 0;
 inline int OPT_elapsed   = 0;
 inline int OPT_cpu       = 0;
 inline int OPT_counts    = 0;
 inline int OPT_pid       = 0;
 inline int PID           = 0;
 inline string NAME       = "";

 dtrace:::BEGIN 
 {              
        /* print header */
        OPT_printid  ? printf("%-8s  ","PID/LWP") : 1;
        OPT_relative ? printf("%8s ","RELATIVE") : 1; 
        OPT_elapsed  ? printf("%7s ","ELAPSD") : 1;   
        OPT_cpu      ? printf("%6s ","CPU") : 1;      
        printf("CALL(args) \t\t = return\n");         

        /* indent depth */
        depth = 0;        
 }                        

 /*
  * Save syscall entry info
  */                       
 pid$target:a.out::entry   
 {                         
        /* set function depth */
        this->fdepth = ++fdepth[probefunc];
        depth += 2;                        

        /* set start details */
        self->start[probefunc,this->fdepth] = timestamp;
        self->vstart[probefunc,this->fdepth] = vtimestamp;

        /* count occurances */
        OPT_counts && OPT_liball ? @Counts[probemod,probefunc] = count() : 1;
        OPT_counts && ! OPT_liball ? @Counts[probefunc] = count() : 1;

        /* print optional fields */
        OPT_printid  ? printf("%5d/%d:  ",pid,tid) : 1;
        OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("      . ") : 1;
        OPT_cpu      ? printf("     . ") : 1;
        OPT_indent   ? printf("%*s",depth,"") : 1;

        /* print main data */
        printf("-> ");
        OPT_liball ? printf("%s:",probemod) : 1;
        printf("%s(0x%X, 0x%X, 0x%X)\t\t\n",probefunc,arg0,arg1,arg2);

 }

 /*
  * Print return data
  */
 /* print 3 arg output - default */
 pid$target:a.out::return
 /self->start[probefunc,fdepth[probefunc]]/
 {
        /* fetch function depth */
        this->fdepth = fdepth[probefunc];

        /* calculate elapsed time */
        this->elapsed = timestamp - self->start[probefunc,this->fdepth];
        self->start[probefunc,this->fdepth] = 0;
        this->cpu = vtimestamp - self->vstart[probefunc,this->fdepth];
        self->vstart[probefunc,this->fdepth] = 0;

        /* print optional fields */
        OPT_printid  ? printf("%5d/%d:  ",pid,tid) : 1;
        OPT_relative ? printf("%8d ",vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ",this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ",this->cpu/1000) : 1;
        OPT_indent   ? printf("%*s",depth,"") : 1;

        /* print main data */
        printf("<- ");
        OPT_liball ? printf("%s:",probemod) : 1;
        printf("%s = %d\n",probefunc,(int)arg0);
        depth -= 2;
        fdepth[probefunc]--;
 }

 /* reset indent depth */
 profile:::tick-1sec
 {
        /*
         * some probes generated by the pid provider have entries
         * but not returns. this is a klude to fix that problem. this
         * also explains fdepth[probefunc] rather than a single depth.
         */
        depth = 0;
 }

 /* print counts */
 dtrace:::END
 {
        OPT_counts ? printf("\n%-49s %16s\n","CALL","COUNT") : 1;
        OPT_counts && OPT_liball ? printa("%-16s %-32s %@16d\n",@Counts) : 1;
        OPT_counts && ! OPT_liball ? printa("%-49s %@16d\n",@Counts) : 1;
 }
: "/usr/lib/dtrace/psinfo.d", line 88: failed to resolve type kernel`struct thread * for identifier curthread: Unknown type name



>How-To-Repeat:
See http://www.freebsd.org/doc/en_US.ISO8859-1/books/handbook/dtrace-enable.html
and run DTraceToolkit applications on FreeBSD 8.0-STABLE.
>Fix:


>Release-Note:
>Audit-Trail:
>Unformatted:

Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200912141024.nBEAOGOD032938>