Compute and display execution statistics

The total run time is displayed along with the number of lines read in the
input logs, the number of records kept and the number of users.

The time it takes to read the input log files and the time it takes to
process the records are computed.

diff --git a/log.c b/log.c
index aeead6107bd12f3ada60b3c7c18556dcc4aa103c..899ebce31aa3a9c00f9bacb3dbf07c6a27bfbbf7 100644 (file)
--- a/log.c
+++ b/log.c
@@ -145,18 +145,30 @@ int main(int argc,char *argv[])
        struct tm *t;
        unsigned long recs1=0UL;
        unsigned long recs2=0UL;
+       unsigned long int lines_read=0UL;
+       unsigned long int records_kept=0UL;
+       unsigned long int nusers=0UL;
        int OutputNonZero = REPORT_EVERY_X_LINES ;
        bool download_flag=false;
        char download_url[MAXLEN];
        struct getwordstruct gwarea;
        longline line;
        time_t tnum;
+       time_t start_time;
+       time_t end_time;
+       time_t read_start_time;
+       time_t read_end_time;
+       time_t process_start_time;
+       time_t process_end_time;
+       double read_elapsed;
+       double process_elapsed;
        struct stat logstat;
        struct userinfostruct *uinfo;
        struct userfilestruct *first_user_file, *ufile, *ufile1, *prev_ufile;
        static int split=0;
        static int convert=0;
        static int output_css=0;
+       static int show_statis=0;
        int option_index;
        static struct option long_options[]=
        {
@@ -167,9 +179,12 @@ int main(int argc,char *argv[])
                {"keeplogs",no_argument,NULL,3},
                {"split",no_argument,&split,1},
                {"splitprefix",required_argument,NULL,'P'},
+               {"statistics",no_argument,&show_statis,1},
                {0,0,0,0}
        };
 
+       start_time=time(NULL);
+
 #ifdef HAVE_LOCALE_H
        setlocale(LC_TIME,"");
 #endif
@@ -791,6 +806,7 @@ int main(int argc,char *argv[])
                }
        }
 
+       read_start_time=time(NULL);
        for (iarq=0 ; iarq<NAccessLog ; iarq++) {
                strcpy(arq,AccessLog[iarq]);
 
@@ -855,6 +871,7 @@ int main(int argc,char *argv[])
 
                while ((linebuf=longline_read(fp_in,line))!=NULL) {
                        blen=strlen(linebuf);
+                       lines_read++;
 
                        if (ilf==ILF_Unknown) {
                                if(strncmp(linebuf,"#Software: Mic",14) == 0) {
@@ -1415,7 +1432,7 @@ int main(int argc,char *argv[])
 
                        nbytes=atol(tam);
                        if (nbytes<0) nbytes=0;
-                       
+
                        elap_time=atol(elap);
                        if (elap_time<0) elap_time=0;
                        if(max_elapsed) {
@@ -1447,6 +1464,7 @@ int main(int argc,char *argv[])
                                uinfo=userinfo_create(user);
                                ufile->user=uinfo;
                                uinfo->id_is_ip=id_is_ip;
+                               nusers++;
                        } else {
                                if (prev_ufile) {
                                        prev_ufile->next=ufile->next;
@@ -1489,6 +1507,7 @@ int main(int argc,char *argv[])
                                debuga(_("Write error in the log file of user %s\n"),user);
                                exit(EXIT_FAILURE);
                        }
+                       records_kept++;
 
                        if(fp_log && ilf!=ILF_Sarg)
                                fprintf(fp_log, "%s\t%s\t%s\t%s\t%s\t%ld\t%s\t%ld\t%s\n",dia,hora,user,ip,url,nbytes,code,elap_time,smartfilter);
@@ -1555,6 +1574,8 @@ int main(int argc,char *argv[])
                        }
                }
        }
+       read_end_time=time(NULL);
+       read_elapsed=(double)read_end_time-(double)read_start_time;
 
        if (debug)
                debuga(_("   Records read: %ld, written: %ld, excluded: %ld\n"),totregsl,totregsg,totregsx);
@@ -1635,7 +1656,7 @@ int main(int argc,char *argv[])
                char end_hour[128];
                char val2[40];
                char val4[255];//val4 must not be bigger than arq_log without fixing the strcpy below
-               
+
                fclose(fp_log);
                safe_strcpy(end_hour,tbuf2,sizeof(end_hour));
                strftime(val2,sizeof(val2),"%d%m%Y",&period.start);
@@ -1687,10 +1708,13 @@ int main(int argc,char *argv[])
                }
        }
 
+       process_start_time=time(NULL);
        if(DataFile[0] != '\0')
                data_file(tmp);
        else
                gerarel();
+       process_end_time=time(NULL);
+       process_elapsed=(double)process_end_time-(double)process_start_time;
 
        if((ReportType & REPORT_TYPE_DENIED) != 0) {
                if (!KeepTempLog && unlink(denied_sort) && errno!=ENOENT)
@@ -1708,6 +1732,20 @@ int main(int argc,char *argv[])
                free(userfile);
        close_usertab();
 
+       end_time=time(NULL);
+
+       if (show_statis) {
+               double elapsed=(double)end_time-(double)start_time;
+               debuga(_("Total execution time: %.0lf seconds\n"),elapsed);
+               if (read_elapsed>0.) {
+                       debuga(_("Lines read: %lu lines in %.0lf seconds (%.0lf lines/s)\n"),lines_read,read_elapsed,(double)lines_read/read_elapsed);
+               }
+               if (process_elapsed>0.) {
+                       debuga(_("Processed records: %lu records in %.0lf seconds (%.0lf records/s)\n"),records_kept,process_elapsed,(double)records_kept/process_elapsed);
+                       debuga(_("Users: %lu users in %.0lf seconds (%.0lf users/s)\n"),nusers,process_elapsed,(double)nusers/process_elapsed);
+               }
+       }
+
        if(debug)
                debuga(_("End\n"));