From: sickfaichezi
Subject: Profiling and Timing
Date: 
Message-ID: <1134005115.333071.215850@z14g2000cwz.googlegroups.com>
Can someone tell me whats wrong with this?

This function took 2 minutes to run, but the profiling only reports
that .3 seconds were used in running the function.

CL-USER> (time (send-mails))
; Compiling LAMBDA NIL:
; Compiling Top-Level Form:

; Evaluation took:
;   125.44 seconds of real time
;   0.31 seconds of user run time
;   0.02 seconds of system run time
;   41,536,836,807 CPU cycles
;   0 page faults and
;   931,792 bytes consed.
;
NIL
CL-USER> (profile:report-time)
   Consed |   Calls | Secs | Sec/Call | Bytes/C. | Name:
-----------------------------------------------------------------------
  198,424 |       4 | .160 |  0.03999 |   49,606 |
ACL-COMPAT.SOCKET:DOTTED-TO-IPADDR
  668,976 |       4 | .140 |  0.03499 |  167,244 |
EMAILSURVEY::CREATE-MESSAGE
   28,616 |       4 | .020 |  0.00499 |    7,154 |
EMAILSURVEY::SEND-MESSAGE
      448 |       4 | .010 |  0.00249 |      112 |
ACL-COMPAT.SOCKET:LOOKUP-HOSTNAME
    9,576 |       1 | .000 |  0.00000 |    9,576 | SEND-MAILS
    7,112 |       4 | .000 |  0.00000 |    1,778 |
EMAILSURVEY::CREATE-HEADER
      232 |       1 | .000 |  0.00000 |      232 |
EMAILSURVEY::GET-UNIQUE-CONTACTS
      352 |       4 | .000 |  0.00000 |       88 |
EMAILSURVEY::GENERATE-SECURE-CODE
      736 |       4 | .000 |  0.00000 |      184 |
EMAILSURVEY::RECORD-CODE
      256 |       4 | .000 |  0.00000 |       64 |
EMAILSURVEY::DESTINATION
    4,416 |       4 | .000 |  0.00000 |    1,104 |
ACL-COMPAT.SOCKET:MAKE-SOCKET
   11,072 |       4 | .000 |  0.00000 |    2,768 |
ACL-COMPAT.SOCKET:IPADDR-TO-DOTTED
      160 |       4 | .000 |  0.00000 |       40 |
ACL-COMPAT.SOCKET:LOCAL-HOST
    1,408 |       4 | .000 |  0.00000 |      352 |
ACL-COMPAT.SOCKET::STRING-TOKENS
        0 |       4 | .000 |  0.00000 |        0 |
ACL-COMPAT.SOCKET::GET-FD
-------------------------------------------------------------------
  931,784 |      54 | .330 |          |          | Total


What happened to the rest?

From: M Jared Finder
Subject: Re: Profiling and Timing
Date: 
Message-ID: <d_ydnSf9i89NMAreRVn-oQ@speakeasy.net>
sickfaichezi wrote:
> Can someone tell me whats wrong with this?
> 
> This function took 2 minutes to run, but the profiling only reports
> that .3 seconds were used in running the function.
> 
> CL-USER> (time (send-mails))
> ; Compiling LAMBDA NIL:
> ; Compiling Top-Level Form:
> 
> ; Evaluation took:
> ;   125.44 seconds of real time
> ;   0.31 seconds of user run time
> ;   0.02 seconds of system run time
> ;   41,536,836,807 CPU cycles
> ;   0 page faults and
> ;   931,792 bytes consed.

Does send-mails do all its work in Lisp, or does it spawn other 
processes?  You're probably getting the total user and system time for 
the *Lisp* end of the code.

   -- MJF
From: Rainer Joswig
Subject: Re: Profiling and Timing
Date: 
Message-ID: <joswig-DADAAD.02363708122005@news-europe.giganews.com>
In article <························@z14g2000cwz.googlegroups.com>,
 "sickfaichezi" <············@gmail.com> wrote:

> Can someone tell me whats wrong with this?
> 
> This function took 2 minutes to run, but the profiling only reports
> that .3 seconds were used in running the function.
> 
> CL-USER> (time (send-mails))
> ; Compiling LAMBDA NIL:
> ; Compiling Top-Level Form:
> 
> ; Evaluation took:
> ;   125.44 seconds of real time
> ;   0.31 seconds of user run time
> ;   0.02 seconds of system run time
> ;   41,536,836,807 CPU cycles
> ;   0 page faults and
> ;   931,792 bytes consed.
> ;
> NIL
> CL-USER> (profile:report-time)
>    Consed |   Calls | Secs | Sec/Call | Bytes/C. | Name:
> -----------------------------------------------------------------------
>   198,424 |       4 | .160 |  0.03999 |   49,606 |
> ACL-COMPAT.SOCKET:DOTTED-TO-IPADDR
>   668,976 |       4 | .140 |  0.03499 |  167,244 |
> EMAILSURVEY::CREATE-MESSAGE
>    28,616 |       4 | .020 |  0.00499 |    7,154 |
> EMAILSURVEY::SEND-MESSAGE
>       448 |       4 | .010 |  0.00249 |      112 |
> ACL-COMPAT.SOCKET:LOOKUP-HOSTNAME
>     9,576 |       1 | .000 |  0.00000 |    9,576 | SEND-MAILS
>     7,112 |       4 | .000 |  0.00000 |    1,778 |
> EMAILSURVEY::CREATE-HEADER
>       232 |       1 | .000 |  0.00000 |      232 |
> EMAILSURVEY::GET-UNIQUE-CONTACTS
>       352 |       4 | .000 |  0.00000 |       88 |
> EMAILSURVEY::GENERATE-SECURE-CODE
>       736 |       4 | .000 |  0.00000 |      184 |
> EMAILSURVEY::RECORD-CODE
>       256 |       4 | .000 |  0.00000 |       64 |
> EMAILSURVEY::DESTINATION
>     4,416 |       4 | .000 |  0.00000 |    1,104 |
> ACL-COMPAT.SOCKET:MAKE-SOCKET
>    11,072 |       4 | .000 |  0.00000 |    2,768 |
> ACL-COMPAT.SOCKET:IPADDR-TO-DOTTED
>       160 |       4 | .000 |  0.00000 |       40 |
> ACL-COMPAT.SOCKET:LOCAL-HOST
>     1,408 |       4 | .000 |  0.00000 |      352 |
> ACL-COMPAT.SOCKET::STRING-TOKENS
>         0 |       4 | .000 |  0.00000 |        0 |
> ACL-COMPAT.SOCKET::GET-FD
> -------------------------------------------------------------------
>   931,784 |      54 | .330 |          |          | Total
> 
> 
> What happened to the rest?

Waiting for DNS lookups? Waiting for network connections?
From: Kaz Kylheku
Subject: Re: Profiling and Timing
Date: 
Message-ID: <1134113683.356035.32720@g49g2000cwa.googlegroups.com>
sickfaichezi wrote:
> Can someone tell me whats wrong with this?
>
> This function took 2 minutes to run, but the profiling only reports
> that .3 seconds were used in running the function.

Two minutes is the real elapsed time. The other measurements are CPU
time, broken into system and user.  CPU time stops when your process or
thread is suspended, wheras real time continues to elapse. Your process
is suspended when it waits for another process to do something, when it
waits for an I/O request to complete, or when it has requested an
explicit scheduling delay (sleep).

User time means time spent executing code on behalf of your thread, but
outside of the operating system kernel. System time is the time spent
executing code in the kernel.

If you're interested in knowing more, check out some textbook book on
computer architectures and the design of operating sytsems.

> CL-USER> (time (send-mails))

Sending e-mail requires I/O. No surprises here!


(There are circumstances in which network communication code can keep
the CPU busy, namely when you are transmitting bulk data over a network
which can take it as fast as your computer can shove it into the
network adapter. The actual packet construction, management of the
protocol state, and the up/down calls through the protocol stack and
the application can take long enough that each time the transmit
routine in the driver is visited, it has finished sending).


> What happened to the rest?

The computer gave the rest of the time to other processes while yours
was suspended. If there were no other processes to run, it dispatched
the idle process: a dummy task built into the operating system to
handle the case when there are no processes to run. The idle process
executes a loop. If the hardware provides it, that loop contains a
special machine language instruction which actually halts the CPU
itself until a hardware interrupt takes place. This state causes the
CPU to drain much less current than if it were to keep spinning in the
loop, and that in turn keeps it cooler. The temperature only rises when
intense computation is performed.
From: Thomas A. Russ
Subject: Re: Profiling and Timing
Date: 
Message-ID: <ymivexxopfm.fsf@sevak.isi.edu>
"sickfaichezi" <············@gmail.com> writes:

> 
> Can someone tell me whats wrong with this?
> 
> This function took 2 minutes to run, but the profiling only reports
> that .3 seconds were used in running the function.
> 
> CL-USER> (time (send-mails))
> ; Compiling LAMBDA NIL:
> ; Compiling Top-Level Form:
> 
> ; Evaluation took:
> ;   125.44 seconds of real time
> ;   0.31 seconds of user run time
> ;   0.02 seconds of system run time
> ;   41,536,836,807 CPU cycles
> ;   0 page faults and
> ;   931,792 bytes consed.
> ;

My first guess for the missing time is some sort of I/O wait.




-- 
Thomas A. Russ,  USC/Information Sciences Institute