#51183 Issue 51165 - add new access log keywords for wtime and optime
Closed 2 years ago by spichugi. Opened 2 years ago by mreynolds.
mreynolds/389-ds-base issue51165  into  master

file modified
+169 -18
@@ -3,7 +3,7 @@ 

  #

  # BEGIN COPYRIGHT BLOCK

  # Copyright (C) 2001 Sun Microsystems, Inc. Used by permission.

- # Copyright (C) 2013 Red Hat, Inc.

+ # Copyright (C) 2020 Red Hat, Inc.

  # All rights reserved.

  #

  # License: GPL (version 3 or any later version).
@@ -55,7 +55,7 @@ 

  my $dataLocation = "/tmp";

  my $startTLSoid = "1.3.6.1.4.1.1466.20037";

  my @statnames=qw(last last_str results srch add mod modrdn moddn cmp del abandon

-                  conns sslconns bind anonbind unbind notesA notesU etime);

+                  conns sslconns bind anonbind unbind notesA notesU notesF etime);

  my $s_stats;

  my $m_stats;

  my $verb = "no";
@@ -211,6 +211,7 @@ 

  my $sslClientFailedCount = 0;

  my $objectclassTopCount= 0;

  my $pagedSearchCount = 0;

+ my $invalidFilterCount = 0;

  my $bindCount = 0;

  my $filterCount = 0;

  my $baseCount = 0;
@@ -258,7 +259,7 @@ 

  # hash db-backed hashes

  my @hashnames = qw(attr rc src rsrc excount conn_hash ip_hash conncount nentries

                     filter base ds6xbadpwd saslmech saslconnop bindlist etime oid

-                    start_time_of_connection end_time_of_connection

+                    start_time_of_connection end_time_of_connection notesf_conn_op

                     notesa_conn_op notesu_conn_op etime_conn_op nentries_conn_op

                     optype_conn_op time_conn_op srch_conn_op del_conn_op mod_conn_op

                     mdn_conn_op cmp_conn_op bind_conn_op unbind_conn_op ext_conn_op
@@ -926,7 +927,7 @@ 

  			}

  			while($op > 0){

  				# The bind op is not the same as the search op that triggered the notes=A.

- 				# We have adjust the key by decrementing the op count until we find the last bind op.

+ 				# We have to adjust the key by decrementing the op count until we find the last bind op.

  				$op--;

  				$binddn_key = "$srvRstCnt,$conn,$op";

  				if (exists($bind_conn_op->{$binddn_key}) && defined($bind_conn_op->{$binddn_key})) {
@@ -1049,9 +1050,60 @@ 

  			}

  		}

  	}

- } # end of unindexed search report

+     print "\n";

+ }

+ 

+ print "Invalid Attribute Filters:    $invalidFilterCount\n";

+ if ($invalidFilterCount > 0 && $verb eq "yes"){

+     my $conn_hash = $hashes->{conn_hash};

+     my $notesf_conn_op = $hashes->{notesf_conn_op};

+     my $time_conn_op = $hashes->{time_conn_op};

+     my $etime_conn_op = $hashes->{etime_conn_op};

+     my $nentries_conn_op = $hashes->{nentries_conn_op};

+     my $filter_conn_op = $hashes->{filter_conn_op};

+     my $bind_conn_op = $hashes->{bind_conn_op};

+     my $notesCount = 1;

+     my $unindexedIp;

+     my $binddn_key;

+     my %uniqFilt = (); # hash of unique filters

+     my %uniqFilter = (); # hash of unique filters bind dn

+     my %uniqBindDNs = (); # hash of unique bind dn's

+     my %uniqBindFilters = (); # hash of filters for a bind DN

+ 

+     while (my ($srcnt_conn_op, $count) = each %{$notesf_conn_op}) {

+         my ($srvRstCnt, $conn, $op) = split(",", $srcnt_conn_op);

+         my $attrIp = getIPfromConn($conn, $srvRstCnt);

+         print "\n  Invalid Attribute Filter #".$notesCount." (notes=F)\n";

+         print "  -  Date/Time:             $time_conn_op->{$srcnt_conn_op}\n";

+         print "  -  Connection Number:     $conn\n";

+         print "  -  Operation Number:      $op\n";

+         print "  -  Etime:                 $etime_conn_op->{$srcnt_conn_op}\n";

+         print "  -  Nentries:              $nentries_conn_op->{$srcnt_conn_op}\n";

+         print "  -  IP Address:            $attrIp\n";

+         if (exists($filter_conn_op->{$srcnt_conn_op}) && defined($filter_conn_op->{$srcnt_conn_op})) {

+             print "  -  Search Filter:         $filter_conn_op->{$srcnt_conn_op}\n";

+             $uniqFilt{$filter_conn_op->{$srcnt_conn_op}}++;

+         }

+         while($op > 0){

+             # The bind op is not the same as the search op that triggered the notes=A.

+             # We have to adjust the key by decrementing the op count until we find the last bind op.

+             $op--;

+             $binddn_key = "$srvRstCnt,$conn,$op";

+             if (exists($bind_conn_op->{$binddn_key}) && defined($bind_conn_op->{$binddn_key})) {

+                 print "  -  Bind DN:               $bind_conn_op->{$binddn_key}\n";

+                 $uniqBindDNs{$bind_conn_op->{$binddn_key}}++;

+                 if( $uniqFilt{$filter_conn_op->{$srcnt_conn_op}} && defined($filter_conn_op->{$srcnt_conn_op})) {

+                     $uniqBindFilters{$bind_conn_op->{$binddn_key}}{$filter_conn_op->{$srcnt_conn_op}}++;

+                     $uniqFilter{$filter_conn_op->{$srcnt_conn_op}}{$bind_conn_op->{$binddn_key}}++;

+                 }

+                 last;

+             }

+         }

+         $notesCount++;

+     }

+     print "\n";

+ }

  

- print "\n";

  print "FDs Taken:                    $fdTaken\n";

  print "FDs Returned:                 $fdReturned\n";

  print "Highest FD Taken:             $highestFdTaken\n\n";
@@ -1386,20 +1438,20 @@ 

  	}

  }

  

- #########################################

- #                                       #

- # Gather and Process the unique etimes  #

- #                                       #

- #########################################

+ ##############################################################

+ #                                                            #

+ # Gather and Process the unique etimes, wtimes, and optimes  #

+ #                                                            #

+ ##############################################################

  

  my $first;

  if ($usage =~ /t/i || $verb eq "yes"){

+ 	# Print the elapsed times (etime)

+ 

  	my $etime = $hashes->{etime};

  	my @ekeys = keys %{$etime};

- 	#

  	# print most often etimes

- 	#

- 	print "\n\n----- Top $sizeCount Most Frequent etimes -----\n\n";

+ 	print "\n\n----- Top $sizeCount Most Frequent etimes (elapsed times) -----\n\n";

  	my $eloop = 0;

  	my $retime = 0;

  	foreach my $et (sort { $etime->{$b} <=> $etime->{$a} } @ekeys) {
@@ -1411,16 +1463,84 @@ 

  		printf "%-8s        %-12s\n", $etime->{ $et }, "etime=$et";

  		$eloop++;

  	}

- 	#

+ 	if ($eloop == 0) {

+ 		print "None";

+ 	}

  	# print longest etimes

- 	#

- 	print "\n\n----- Top $sizeCount Longest etimes -----\n\n";

+ 	print "\n\n----- Top $sizeCount Longest etimes (elapsed times) -----\n\n";

  	$eloop = 0;

  	foreach my $et (sort { $b <=> $a } @ekeys) {

  		if ($eloop == $sizeCount) { last; }

  		printf "%-12s    %-10s\n","etime=$et",$etime->{ $et };

  		$eloop++;

  	}

+ 	if ($eloop == 0) {

+ 		print "None";

+ 	}

+ 

+ 	# Print the wait times (wtime)

+ 

+ 	my $wtime = $hashes->{wtime};

+ 	my @wkeys = keys %{$wtime};

+ 	# print most often wtimes

+ 	print "\n\n----- Top $sizeCount Most Frequent wtimes (wait times) -----\n\n";

+ 	$eloop = 0;

+ 	$retime = 0;

+ 	foreach my $et (sort { $wtime->{$b} <=> $wtime->{$a} } @wkeys) {

+ 		if ($eloop == $sizeCount) { last; }

+ 		if ($retime ne "2"){

+ 			$first = $et;

+ 			$retime = "2";

+ 		}

+ 		printf "%-8s        %-12s\n", $wtime->{ $et }, "wtime=$et";

+ 		$eloop++;

+ 	}

+ 	if ($eloop == 0) {

+ 		print "None";

+ 	}

+ 	# print longest wtimes

+ 	print "\n\n----- Top $sizeCount Longest wtimes (wait times) -----\n\n";

+ 	$eloop = 0;

+ 	foreach my $et (sort { $b <=> $a } @wkeys) {

+ 		if ($eloop == $sizeCount) { last; }

+ 		printf "%-12s    %-10s\n","wtime=$et",$wtime->{ $et };

+ 		$eloop++;

+ 	}

+ 	if ($eloop == 0) {

+ 		print "None";

+ 	}

+ 

+ 	# Print the operation times (optime)

+ 

+ 	my $optime = $hashes->{optime};

+ 	my @opkeys = keys %{$optime};

+ 	# print most often optimes

+ 	print "\n\n----- Top $sizeCount Most Frequent optimes (actual operation times) -----\n\n";

+ 	$eloop = 0;

+ 	$retime = 0;

+ 	foreach my $et (sort { $optime->{$b} <=> $optime->{$a} } @opkeys) {

+ 		if ($eloop == $sizeCount) { last; }

+ 		if ($retime ne "2"){

+ 			$first = $et;

+ 			$retime = "2";

+ 		}

+ 		printf "%-8s        %-12s\n", $optime->{ $et }, "optime=$et";

+ 		$eloop++;

+ 	}

+ 	if ($eloop == 0) {

+ 		print "None";

+ 	}

+ 	# print longest optimes

+ 	print "\n\n----- Top $sizeCount Longest optimes (actual operation times) -----\n\n";

+ 	$eloop = 0;

+ 	foreach my $et (sort { $b <=> $a } @opkeys) {

+ 		if ($eloop == $sizeCount) { last; }

+ 		printf "%-12s    %-10s\n","optime=$et",$optime->{ $et };

+ 		$eloop++;

+ 	}

+ 	if ($eloop == 0) {

+ 		print "None";

+ 	}

  }

  

  #######################################
@@ -2152,6 +2272,26 @@ 

  	if (m/ RESULT err=/ && m/ notes=[A-Z,]*P/){

  		$pagedSearchCount++;

  	}

+ 	if (m/ RESULT err=/ && m/ notes=[A-Z,]*F/){

+ 		$invalidFilterCount++;

+ 		$con = "";

+ 		if ($_ =~ /conn= *([0-9A-Z]+)/i){

+ 			$con = $1;

+ 			if ($_ =~ /op= *([0-9\-]+)/i){ $op = $1;}

+ 		}

+ 

+ 		if($reportStats){ inc_stats('notesF',$s_stats,$m_stats); }

+         if ($usage =~ /u/ || $usage =~ /U/ || $verb eq "yes"){

+             if($_ =~ /etime= *([0-9.]+)/i ){

+                 if($1 >= $minEtime){

+                     $hashes->{etime_conn_op}->{"$serverRestartCount,$con,$op"} = $1;

+                     $hashes->{notesf_conn_op}->{"$serverRestartCount,$con,$op"}++;

+                     if ($_ =~ / *([0-9a-z:\/]+)/i){ $hashes->{time_conn_op}->{"$serverRestartCount,$con,$op"} = $1; }

+                     if ($_ =~ /nentries= *([0-9]+)/i ){ $hashes->{nentries_conn_op}->{"$serverRestartCount,$con,$op"} = $1; }

+                 }

+             }

+         }

+ 	}

  	if (m/ notes=[A-Z,]*A/){

  		$con = "";

  		if ($_ =~ /conn= *([0-9A-Z]+)/i){
@@ -2435,6 +2575,16 @@ 

  		if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{etime}->{$etime_val}++; }

  		if ($reportStats){ inc_stats_val('etime',$etime_val,$s_stats,$m_stats); }

  	}

+ 	if ($_ =~ /wtime= *([0-9.]+)/ ) {

+ 		my $wtime_val = $1;

+ 		if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{wtime}->{$wtime_val}++; }

+ 		if ($reportStats){ inc_stats_val('wtime',$wtime_val,$s_stats,$m_stats); }

+ 	}

+ 	if ($_ =~ /optime= *([0-9.]+)/ ) {

+ 		my $optime_val = $1;

+ 		if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{optime}->{$optime_val}++; }

+ 		if ($reportStats){ inc_stats_val('optime',$optime_val,$s_stats,$m_stats); }

+ 	}

  	if ($_ =~ / tag=101 / || $_ =~ / tag=111 / || $_ =~ / tag=100 / || $_ =~ / tag=115 /){

  		if ($_ =~ / nentries= *([0-9]+)/i ){ 

  			my $nents = $1;
@@ -2555,7 +2705,7 @@ 

  			}

  		}

  	}

- 	if (/ RESULT err=/ && / tag=97 nentries=0 etime=/ && $_ =~ /dn=\"(.*)\"/i){

+ 	if (/ RESULT err=/ && / tag=97 nentries=0 / && $_ =~ /dn=\"(.*)\"/i){

  		# Check if this is a sasl bind, if see we need to add the RESULT's dn as a bind dn

  		my $binddn = $1;

  		my ($conn, $op);
@@ -2680,6 +2830,7 @@ 

  						 $stats->{'unbind'},

  						 $stats->{'notesA'},

  						 $stats->{'notesU'},

+ 						 $stats->{'notesF'},

  						 $stats->{'etime'}),

  					"\n" );

  			} else {

@@ -441,6 +441,9 @@ 

      internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);

      pwpolicy = new_passwdPolicy(pb, slapi_entry_get_dn(e));

  

+     /* Set the time we actually started the operation */

+     slapi_operation_set_time_started(operation);

+ 

      /* target spec is used to decide which plugins are applicable for the operation */

      operation_set_target_spec(operation, slapi_entry_get_sdn(e));

  

@@ -87,6 +87,10 @@ 

          send_ldap_result(pb, LDAP_OPERATIONS_ERROR, NULL, NULL, 0, NULL);

          goto free_and_return;

      }

+ 

+     /* Set the time we actually started the operation */

+     slapi_operation_set_time_started(pb_op);

+ 

      ber = pb_op->o_ber;

  

      /*

@@ -236,6 +236,9 @@ 

      slapi_pblock_get(pb, SLAPI_OPERATION, &operation);

      internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);

  

+     /* Set the time we actually started the operation */

+     slapi_operation_set_time_started(operation);

+ 

      sdn = slapi_sdn_new_dn_byval(rawdn);

      dn = slapi_sdn_get_dn(sdn);

      slapi_pblock_set(pb, SLAPI_DELETE_TARGET_SDN, (void *)sdn);

@@ -626,6 +626,9 @@ 

      slapi_pblock_get(pb, SLAPI_SKIP_MODIFIED_ATTRS, &skip_modified_attrs);

      slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);

  

+     /* Set the time we actually started the operation */

+     slapi_operation_set_time_started(operation);

+ 

      if (sdn) {

          passin_sdn = 1;

      } else {

@@ -417,6 +417,9 @@ 

      internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);

      slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);

  

+     /* Set the time we actually started the operation */

+     slapi_operation_set_time_started(operation);

+ 

      /*

       * If ownership has not been passed to this function, we replace the

       * string input fields within the pblock with strdup'd copies.  Why?

@@ -651,3 +651,27 @@ 

  {

      slapi_timespec_expire_rel(timeout, &(o->o_hr_time_rel), expiry);

  }

+ 

+ /* Set the time the operation actually started */

+ void

+ slapi_operation_set_time_started(Slapi_Operation *o)

+ {

+ 	clock_gettime(CLOCK_MONOTONIC, &(o->o_hr_time_started_rel));

+ }

+ 

+ /* The time diff of how long the operation took once it actually started */

+ void

+ slapi_operation_op_time_elapsed(Slapi_Operation *o, struct timespec *elapsed)

+ {

+     struct timespec o_hr_time_now;

+     clock_gettime(CLOCK_MONOTONIC, &o_hr_time_now);

+ 

+     slapi_timespec_diff(&o_hr_time_now, &(o->o_hr_time_started_rel), elapsed);

+ }

+ 

+ /* The time diff the operation waited in the work queue */

+ void

+ slapi_operation_workq_time_elapsed(Slapi_Operation *o, struct timespec *elapsed)

+ {

+     slapi_timespec_diff(&(o->o_hr_time_started_rel), &(o->o_hr_time_rel), elapsed);

+ }

@@ -284,6 +284,9 @@ 

      slapi_pblock_get(pb, SLAPI_SEARCH_TARGET_SDN, &sdn);

      slapi_pblock_get(pb, SLAPI_OPERATION, &operation);

  

+     /* Set the time we actually started the operation */

+     slapi_operation_set_time_started(operation);

+ 

      if (NULL == sdn) {

          sdn = slapi_sdn_new_dn_byval(base);

          slapi_pblock_set(pb, SLAPI_SEARCH_TARGET_SDN, sdn);

file modified
+29 -20
@@ -1975,6 +1975,8 @@ 

      CSN *operationcsn = NULL;

      char csn_str[CSN_STRSIZE + 5];

      char etime[ETIME_BUFSIZ] = {0};

+     char wtime[ETIME_BUFSIZ] = {0};

+     char optime[ETIME_BUFSIZ] = {0};

      int pr_idx = -1;

      int pr_cookie = -1;

      uint32_t operation_notes;
@@ -1982,19 +1984,26 @@ 

      int32_t op_id;

      int32_t op_internal_id;

      int32_t op_nested_count;

+     struct timespec o_hr_time_end;

  

      get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count);

- 

      slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx);

      slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie);

- 

      internal_op = operation_is_flag_set(op, OP_FLAG_INTERNAL);

  

-     struct timespec o_hr_time_end;

+     /* total elapsed time */

      slapi_operation_time_elapsed(op, &o_hr_time_end);

+     snprintf(etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

+ 

+     /* wait time */

+     slapi_operation_workq_time_elapsed(op, &o_hr_time_end);

+     snprintf(wtime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

+ 

+     /* op time */

+     slapi_operation_op_time_elapsed(op, &o_hr_time_end);

+     snprintf(optime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

  

  

-     snprintf(etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

  

      operation_notes = slapi_pblock_get_operation_notes(pb);

  
@@ -2025,16 +2034,16 @@ 

          if (!internal_op) {

              slapi_log_access(LDAP_DEBUG_STATS,

                               "conn=%" PRIu64 " op=%d RESULT err=%d"

-                              " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"

+                              " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"

                               ", SASL bind in progress\n",

                               op->o_connid,

                               op->o_opid,

                               err, tag, nentries,

-                              etime,

+                              wtime, optime, etime,

                               notes_str, csn_str);

          } else {

  

- #define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s, SASL bind in progress\n"

+ #define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s, SASL bind in progress\n"

              slapi_log_access(LDAP_DEBUG_ARGS,

                               connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_SASLMSG_FMT :

                                             LOG_CONN_OP_FMT_EXT_INT LOG_SASLMSG_FMT,
@@ -2043,7 +2052,7 @@ 

                               op_internal_id,

                               op_nested_count,

                               err, tag, nentries,

-                              etime,

+                              wtime, optime, etime,

                               notes_str, csn_str);

          }

      } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) {
@@ -2057,15 +2066,15 @@ 

          if (!internal_op) {

              slapi_log_access(LDAP_DEBUG_STATS,

                               "conn=%" PRIu64 " op=%d RESULT err=%d"

-                              " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"

+                              " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"

                               " dn=\"%s\"\n",

                               op->o_connid,

                               op->o_opid,

                               err, tag, nentries,

-                              etime,

+                              wtime, optime, etime,

                               notes_str, csn_str, dn ? dn : "");

          } else {

- #define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s dn=\"%s\"\n"

+ #define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s dn=\"%s\"\n"

              slapi_log_access(LDAP_DEBUG_ARGS,

                               connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_BINDMSG_FMT :

                                             LOG_CONN_OP_FMT_EXT_INT LOG_BINDMSG_FMT,
@@ -2074,7 +2083,7 @@ 

                               op_internal_id,

                               op_nested_count,

                               err, tag, nentries,

-                              etime,

+                              wtime, optime, etime,

                               notes_str, csn_str, dn ? dn : "");

          }

          slapi_ch_free((void **)&dn);
@@ -2083,15 +2092,15 @@ 

              if (!internal_op) {

                  slapi_log_access(LDAP_DEBUG_STATS,

                                   "conn=%" PRIu64 " op=%d RESULT err=%d"

-                                  " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"

+                                  " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"

                                   " pr_idx=%d pr_cookie=%d\n",

                                   op->o_connid,

                                   op->o_opid,

                                   err, tag, nentries,

-                                  etime,

+                                  wtime, optime, etime,

                                   notes_str, csn_str, pr_idx, pr_cookie);

              } else {

- #define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s pr_idx=%d pr_cookie=%d \n"

+ #define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s pr_idx=%d pr_cookie=%d \n"

                  slapi_log_access(LDAP_DEBUG_ARGS,

                                   connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_PRMSG_FMT :

                                                 LOG_CONN_OP_FMT_EXT_INT LOG_PRMSG_FMT,
@@ -2100,7 +2109,7 @@ 

                                   op_internal_id,

                                   op_nested_count,

                                   err, tag, nentries,

-                                  etime,

+                                  wtime, optime, etime,

                                   notes_str, csn_str, pr_idx, pr_cookie);

              }

          } else if (!internal_op) {
@@ -2114,11 +2123,11 @@ 

              }

              slapi_log_access(LDAP_DEBUG_STATS,

                               "conn=%" PRIu64 " op=%d RESULT err=%d"

-                              " tag=%" BERTAG_T " nentries=%d etime=%s%s%s%s\n",

+                              " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s\n",

                               op->o_connid,

                               op->o_opid,

                               err, tag, nentries,

-                              etime,

+                              wtime, optime, etime,

                               notes_str, csn_str, ext_str);

              if (pbtxt) {

                  /* if !pbtxt ==> ext_str == "".  Don't free ext_str. */
@@ -2126,7 +2135,7 @@ 

              }

          } else {

              int optype;

- #define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n"

+ #define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s\n"

              slapi_log_access(LDAP_DEBUG_ARGS,

                               connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_MSG_FMT :

                                             LOG_CONN_OP_FMT_EXT_INT LOG_MSG_FMT,
@@ -2135,7 +2144,7 @@ 

                               op_internal_id,

                               op_nested_count,

                               err, tag, nentries,

-                              etime,

+                              wtime, optime, etime,

                               notes_str, csn_str);

              /*

               *  If this is an unindexed search we should log it in the error log if

file modified
+7 -6
@@ -1541,16 +1541,17 @@ 

   */

  typedef struct op

  {

-     BerElement *o_ber;             /* ber of the request          */

-     ber_int_t o_msgid;             /* msgid of the request          */

-     ber_tag_t o_tag;               /* tag of the request          */

+     BerElement *o_ber;             /* ber of the request */

+     ber_int_t o_msgid;             /* msgid of the request */

+     ber_tag_t o_tag;               /* tag of the request */

      struct timespec o_hr_time_rel; /* internal system time op initiated */

      struct timespec o_hr_time_utc; /* utc system time op initiated */

-     int o_isroot;                  /* requestor is manager          */

+     struct timespec o_hr_time_started_rel; /* internal system time op started */

+     int o_isroot;                  /* requestor is manager */

      Slapi_DN o_sdn;                /* dn bound when op was initiated */

-     char *o_authtype;              /* auth method used to bind dn      */

+     char *o_authtype;              /* auth method used to bind dn */

      int o_ssf;                     /* ssf for this operation (highest between SASL and TLS/SSL) */

-     int o_opid;                    /* id of this operation          */

+     int o_opid;                    /* id of this operation */

      PRUint64 o_connid;             /* id of conn initiating this op; for logging only */

      void *o_handler_data;

      result_handler o_result_handler;

@@ -8218,13 +8218,29 @@ 

   */

  void slapi_operation_time_initiated(Slapi_Operation *o, struct timespec *initiated);

  /**

-  * Given an operation and a timeout, return a populate struct with the expiry

-  * time of the operation suitable for checking with slapi_timespec_expire_check

+  * Given an operation, determine the time elapsed since the op

+  * was actually started.

   *

-  * \param Slapi_Operation o - the operation that is in progress

-  * \param time_t timeout the seconds relative to operation initiation to expiry at.

-  * \param struct timespec *expiry the timespec to popluate with the relative expiry.

+  * \param Slapi_Operation o - the operation which is inprogress

+  * \param struct timespec *elapsed - location where the time difference will be

+  * placed.

+  */

+ void slapi_operation_op_time_elapsed(Slapi_Operation *o, struct timespec *elapsed);

+ /**

+  * Given an operation, determine the time elapsed that the op spent

+  * in the work queue before actually being dispatched to a worker thread

+  *

+  * \param Slapi_Operation o - the operation which is inprogress

+  * \param struct timespec *elapsed - location where the time difference will be

+  * placed.

+  */

+ void slapi_operation_workq_time_elapsed(Slapi_Operation *o, struct timespec *elapsed);

+ /**

+  * Set the time the operation actually started

+  *

+  * \param Slapi_Operation o - the operation which is inprogress

   */

+ void slapi_operation_set_time_started(Slapi_Operation *o);

  #endif

  

  /**

Description:

In addition to the "etime" stat in the access we can also add the time the operation spent in the work queue, and how long the actual operation took. We now have "wtime" and "optime" to track these stats in the access log.

Also updated logconf for notes=F (related to a different ticket), and stats for wtime and optime.

relates: https://pagure.io/389-ds-base/issue/51165

rebased onto f104f52797f1c83f9e176c0dc02a9fbda2d971b3

2 years ago

All looks pretty good to me! Ack :)

Ack for me as well.
Just a question regarding the access log format. It makes sense to group [ewo]time however up to new we always append new record to the end (page result, extend string..). This new format can impact customer scripts, should we care about a "compatible" format.

I don't think we should - even appending items could break log parsers, and others, it's not a "stable" part of our api. To make guarantees like this we'd need structured logging that output in json I think.

Ack for me as well.
Just a question regarding the access log format. It makes sense to group [ewo]time however up to new we always append new record to the end (page result, extend string..). This new format can impact customer scripts, should we care about a "compatible" format.

Actually that is why I left "etime" at the end. So the end of the access log RESULT line is the same. The new keywords are injected in the middle, but I also updated logconv to handle the change as well. Our tools handle the change fine, so I don't think we need to worry about custom scripts or adding a new config option to adjust the format.

rebased onto 3246fe7

2 years ago

Pull-Request has been merged by mreynolds

2 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/4236

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.

Pull-Request has been closed by spichugi

2 years ago