From 282edde7950ceb2515d74fdbcc0a188131769d74 Mon Sep 17 00:00:00 2001

From: Mark Reynolds <mreynolds@redhat.com>

Date: Tue, 23 Jun 2020 16:38:55 -0400

Subject: [PATCH] Issue 51165 - add new access log keywords for wtime and

 optime

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

Reviewed by: ?

---

 ldap/admin/src/logconv.pl         | 187 +++++++++++++++++++++++++++---

 ldap/servers/slapd/add.c          |   3 +

 ldap/servers/slapd/bind.c         |   4 +

 ldap/servers/slapd/delete.c       |   3 +

 ldap/servers/slapd/modify.c       |   3 +

 ldap/servers/slapd/modrdn.c       |   3 +

 ldap/servers/slapd/operation.c    |  24 ++++

 ldap/servers/slapd/opshared.c     |   3 +

 ldap/servers/slapd/result.c       |  49 ++++----

 ldap/servers/slapd/slap.h         |  13 ++-

 ldap/servers/slapd/slapi-plugin.h |  26 ++++-

 11 files changed, 269 insertions(+), 49 deletions(-)

diff --git a/ldap/admin/src/logconv.pl b/ldap/admin/src/logconv.pl

index f4808a101..1ed44a888 100755

--- a/ldap/admin/src/logconv.pl

+++ b/ldap/admin/src/logconv.pl

@@ -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 $reportStats = "";

 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 $sslClientBindCount = 0;

 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 @@ map {$conn{$_} = $_} @conncodes;

 # 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 @@ if ($verb eq "yes" || $usage =~ /u/ || $usage =~ /U/){

 			}

 			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 @@ if ($verb eq "yes" || $usage =~ /u/ || $usage =~ /U/){

 			}

 		}

 	}

-} # 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 @@ if ($usage =~ /l/ || $verb eq "yes"){

 	}

 }

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

-#                                       #

-# 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 @@ if ($usage =~ /t/i || $verb eq "yes"){

 		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 @@ sub parseLineNormal

 	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 @@ sub parseLineNormal

 		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 @@ sub parseLineNormal

 			}

 		}

 	}

-	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 @@ print_stats_block

 						 $stats->{'unbind'},

 						 $stats->{'notesA'},

 						 $stats->{'notesU'},

+						 $stats->{'notesF'},

 						 $stats->{'etime'}),

 					"\n" );

 			} else {

diff --git a/ldap/servers/slapd/add.c b/ldap/servers/slapd/add.c

index 06ca1ee79..52c64fa3c 100644

--- a/ldap/servers/slapd/add.c

+++ b/ldap/servers/slapd/add.c

@@ -441,6 +441,9 @@ op_shared_add(Slapi_PBlock *pb)

     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));

diff --git a/ldap/servers/slapd/bind.c b/ldap/servers/slapd/bind.c

index 310216e89..55f865077 100644

--- a/ldap/servers/slapd/bind.c

+++ b/ldap/servers/slapd/bind.c

@@ -87,6 +87,10 @@ do_bind(Slapi_PBlock *pb)

         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;

     /*

diff --git a/ldap/servers/slapd/delete.c b/ldap/servers/slapd/delete.c

index c0e61adf1..1a7209317 100644

--- a/ldap/servers/slapd/delete.c

+++ b/ldap/servers/slapd/delete.c

@@ -236,6 +236,9 @@ op_shared_delete(Slapi_PBlock *pb)

     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);

diff --git a/ldap/servers/slapd/modify.c b/ldap/servers/slapd/modify.c

index 259bedfff..a186dbde3 100644

--- a/ldap/servers/slapd/modify.c

+++ b/ldap/servers/slapd/modify.c

@@ -626,6 +626,9 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw)

     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 {

diff --git a/ldap/servers/slapd/modrdn.c b/ldap/servers/slapd/modrdn.c

index 3efe584a7..e04916b83 100644

--- a/ldap/servers/slapd/modrdn.c

+++ b/ldap/servers/slapd/modrdn.c

@@ -417,6 +417,9 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args)

     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?

diff --git a/ldap/servers/slapd/operation.c b/ldap/servers/slapd/operation.c

index ff16cd906..4dd3481c7 100644

--- a/ldap/servers/slapd/operation.c

+++ b/ldap/servers/slapd/operation.c

@@ -651,3 +651,27 @@ slapi_operation_time_expiry(Slapi_Operation *o, time_t timeout, struct timespec

 {

     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);

+}

diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c

index 9fe78655c..c0bc5dcd0 100644

--- a/ldap/servers/slapd/opshared.c

+++ b/ldap/servers/slapd/opshared.c

@@ -284,6 +284,9 @@ op_shared_search(Slapi_PBlock *pb, int send_result)

     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);

diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c

index 0b13c30e9..61efb6f8d 100644

--- a/ldap/servers/slapd/result.c

+++ b/ldap/servers/slapd/result.c

@@ -1975,6 +1975,8 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

     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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

     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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

         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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

                              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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

         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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

                              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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

             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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

                                  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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

             }

             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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

             }

         } 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 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

                              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

diff --git a/ldap/servers/slapd/slap.h b/ldap/servers/slapd/slap.h

index cef8c789c..8e76393c3 100644

--- a/ldap/servers/slapd/slap.h

+++ b/ldap/servers/slapd/slap.h

@@ -1538,16 +1538,17 @@ typedef struct slapi_operation_results

  */

 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;

diff --git a/ldap/servers/slapd/slapi-plugin.h b/ldap/servers/slapd/slapi-plugin.h

index 834a98742..8d9c3fa6a 100644

--- a/ldap/servers/slapd/slapi-plugin.h

+++ b/ldap/servers/slapd/slapi-plugin.h

@@ -8210,13 +8210,29 @@ void slapi_operation_time_elapsed(Slapi_Operation *o, struct timespec *elapsed);

  */

 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

 /**

-- 

2.26.2