feat: measure and log duration of request and mongodb / off-query que… (

openfoodfacts#10557)

As discussed in the infrastructure call today, this PR creates a request
stats log file that contains in particular the time spent on each
request, and time spent on specific parts (currently only off-query and
mongodb queries, but we could measure other parts, like computiing
attributes for all products etc.)

Each product opener request generates 1 line in the log. The log can
then be filtered, processed etc. to generate stats, averages etc. by
route etc.

Sample output:

```
[2024/07/16 16:02:54] [6322] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {facets_tags => 1,hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',original_query_string => 'category/plant-based-foods',request => 'UAKAojOQSh9DkCIL',request_duration => '1.07953190803528',route => 'facets_products',tags => [{canon_tagid => 'en:plant-based-foods',display_tag => 'Plant-based foods',new_tagid => 'en:plant-based-foods',new_tagid_path => '/category/plant-based-foods',tag => 'en:plant-based-foods',tag_prefix => '',tagid => 'en:plant-based-foods',tagtype => 'categories',tagtype_name => 'category',tagtype_path => '/categories'}]} request_stats
[2024/07/16 16:03:22] [34119] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {facets_tags => 1,hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',mongodb_query_count_duration => '0.149086952209473',mongodb_query_duration => '0.0049130916595459',off_query_count_tags_query_duration => '0.0157339572906494',original_query_string => 'category/plant-based-foods',request => 'Cf8BRMfpkrkvDo5r',request_duration => '1.04712390899658',route => 'facets_products',tags => [{canon_tagid => 'en:plant-based-foods',display_tag => 'Plant-based foods',new_tagid => 'en:plant-based-foods',new_tagid_path => '/category/plant-based-foods',tag => 'en:plant-based-foods',tag_prefix => '',tagid => 'en:plant-based-foods',tagtype => 'categories',tagtype_name => 'category',tagtype_path => '/categories'}]} request_stats
[2024/07/16 16:03:22] [34310] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {api_action => 'attribute_groups',hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',original_query_string => 'api/v0/attribute_groups',request => 'LA6egYtTcXy2PEzB',request_duration => '0.0332939624786377',route => 'api'} request_stats
[2024/07/16 16:08:20] [331813] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',original_query_string => '',request => 'XYsmC846i7lx4y5Q',request_duration => '0.574708938598633',route => 'index'} request_stats
[2024/07/16 16:08:23] [335260] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {code => '3229820100234',hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',original_query_string => 'product/3229820100234/filled-dark-chocolate-bjorg',request => 'tKwnWARpucerfJZB',request_duration => '0.423907995223999',rev => undef,route => 'product'} request_stats
[2024/07/16 16:08:31] [343612] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {facets_tags => 0,groupby_tagtype => 'labels',hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',mongodb_aggregate_count_duration => '0.101968050003052',mongodb_aggregate_query_duration => '0.43549108505249',off_query_aggregate_tags_query_duration => '0.00300002098083496',original_query_string => 'labels',request => '9HKK8uXPV6T7cN4Y',request_duration => '0.600616216659546',route => 'facets_tags',tags => []} request_stats
[2024/07/16 16:08:34] [346268] /opt/product-opener/lib/ProductOpener/RequestStats.pm 76 requeststats {facets_tags => 1,hostname => 'world.openfoodfacts.localhost',ip => '192.168.16.1',mongodb_query_count_duration => '0.120925903320312',mongodb_query_duration => '0.00329804420471191',off_query_count_tags_query_duration => '0.0101730823516846',original_query_string => 'label/vegetarian',request => 'l7KQVKiAFXomtGQw',request_duration => '0.877622842788696',route => 'facets_products',tags => [{canon_tagid => 'en:vegetarian',display_tag => 'Vegetarian',new_tagid => 'en:vegetarian',new_tagid_path => '/label/vegetarian',tag => 'en:vegetarian',tag_prefix => '',tagid => 'en:vegetarian',tagtype => 'labels',tagtype_name => 'label',tagtype_path => '/labels'}]} request_stats
```

conf/log.conf

@@ -1,19 +1,34 @@
 log4perl.rootLogger= sub {return ($ENV{LOG_LEVEL_ROOT} // "ERROR") . ", LOGFILE";}
 log4perl.logger.mongodb= sub {return ($ENV{LOG_LEVEL_MONGODB} // "INFO") . ", MONGODB_LOGFILE";}
 log4perl.logger.ratelimiter = sub {return ($ENV{LOG_LEVEL_RATE_LIMITER} // "INFO") . ", RATELIMITER_LOGFILE";}
+log4perl.logger.requeststats = sub {return ($ENV{LOG_LEVEL_REQUEST_STATS} // "INFO") . ", REQUESTSTATS_LOGFILE";}
 log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_context; use Data::Dumper (); local $Data::Dumper::Indent    = 0; local $Data::Dumper::Terse     = 1; local $Data::Dumper::Sortkeys  = 1; local $Data::Dumper::Quotekeys = 0; local $Data::Dumper::Deparse= 1; my $str = Data::Dumper::Dumper($context); $str =~ s/[\n\r]/ /g; return $str; }
+log4perl.PatternLayout.cspec.J = sub { my $context = Log::Log4perl::MDC->get_context; use JSON::MaybeXS; my $json_utf8 = JSON::MaybeXS->new->utf8(1)->allow_nonref->canonical; my $str = $json_utf8->encode($context); return $str; }
+
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.LOGFILE.filename=/mnt/podata/logs/log4perl.log
 log4perl.appender.LOGFILE.mode=append
+log4perl.appender.LOGFILE.autoflush=1
 log4perl.appender.LOGFILE.layout=PatternLayout
 log4perl.appender.LOGFILE.layout.ConversionPattern=[%d] [%r] %F %L %c %S %m{chomp}%n
+
 log4perl.appender.MONGODB_LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.MONGODB_LOGFILE.filename=/mnt/podata/logs/mongodb_log4perl.log
 log4perl.appender.MONGODB_LOGFILE.mode=append
+log4perl.appender.MONGODB_LOGFILE.autoflush=1
 log4perl.appender.MONGODB_LOGFILE.layout=PatternLayout
 log4perl.appender.MONGODB_LOGFILE.layout.ConversionPattern=[%d] [%r] %F %L %c %S %m{chomp}%n
+
 log4perl.appender.RATELIMITER_LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.RATELIMITER_LOGFILE.filename=/mnt/podata/logs/ratelimiter_log4perl.log
 log4perl.appender.RATELIMITER_LOGFILE.mode=append
+log4perl.appender.RATELIMITER_LOGFILE.autoflush=1
 log4perl.appender.RATELIMITER_LOGFILE.layout=PatternLayout
 log4perl.appender.RATELIMITER_LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
+
+log4perl.appender.REQUESTSTATS_LOGFILE=Log::Log4perl::Appender::File
+log4perl.appender.REQUESTSTATS_LOGFILE.filename=/mnt/podata/logs/requeststats_log4perl.log
+log4perl.appender.REQUESTSTATS_LOGFILE.mode=append
+log4perl.appender.REQUESTSTATS_LOGFILE.autoflush=1
+log4perl.appender.REQUESTSTATS_LOGFILE.layout=PatternLayout
+log4perl.appender.REQUESTSTATS_LOGFILE.layout.ConversionPattern=%J %n

conf/obf-log.conf

@@ -1,19 +1,35 @@
 log4perl.rootLogger=ERROR, LOGFILE
 log4perl.logger.mongodb=INFO, MONGODB_LOGFILE
+log4perl.logger.ratelimiter=INFO, RATELIMITER_LOGFILE
+log4perl.logger.requeststats=INFO, REQUESTSTATS_LOGFILE
 
 log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_context; use Data::Dumper (); local $Data::Dumper::Indent    = 0; local $Data::Dumper::Terse     = 1; local $Data::Dumper::Sortkeys  = 1; local $Data::Dumper::Quotekeys = 0; local $Data::Dumper::Deparse   = 1; my $str = Data::Dumper::Dumper($context); $str =~ s/[\n\r]/ /g; return $str; }
+log4perl.PatternLayout.cspec.J = sub { my $context = Log::Log4perl::MDC->get_context; use JSON::MaybeXS; my $json_utf8 = JSON::MaybeXS->new->utf8(1)->allow_nonref->canonical; my $str = $json_utf8->encode($context); return $str; }
 
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.LOGFILE.filename=/srv/obf/logs/log4perl.log
 log4perl.appender.LOGFILE.mode=append
-
+log4perl.appender.LOGFILE.autoflush=0
 log4perl.appender.LOGFILE.layout=PatternLayout
-log4perl.appender.LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n
+log4perl.appender.LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
 
 log4perl.appender.MONGODB_LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.MONGODB_LOGFILE.filename=/srv/obf/logs/mongodb_log4perl.log
 log4perl.appender.MONGODB_LOGFILE.mode=append
-
+log4perl.appender.MONGODB_LOGFILE.autoflush=0
 log4perl.appender.MONGODB_LOGFILE.layout=PatternLayout
-log4perl.appender.MONGODB_LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n
+log4perl.appender.MONGODB_LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
+
+log4perl.appender.RATELIMITER_LOGFILE=Log::Log4perl::Appender::File
+log4perl.appender.RATELIMITER_LOGFILE.filename=/srv/obf/logs/ratelimiter_log4perl.log
+log4perl.appender.RATELIMITER_LOGFILE.mode=append
+log4perl.appender.RATELIMITER_LOGFILE.autoflush=0
+log4perl.appender.RATELIMITER_LOGFILE.layout=PatternLayout
+log4perl.appender.RATELIMITER_LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
 
+log4perl.appender.REQUESTSTATS_LOGFILE=Log::Log4perl::Appender::File
+log4perl.appender.REQUESTSTATS_LOGFILE.filename=/srv/obf/logs/requeststats_log4perl.log
+log4perl.appender.REQUESTSTATS_LOGFILE.mode=append
+log4perl.appender.REQUESTSTATS_LOGFILE.autoflush=0
+log4perl.appender.REQUESTSTATS_LOGFILE.layout=PatternLayout
+log4perl.appender.REQUESTSTATS_LOGFILE.layout.ConversionPattern=%J %n

conf/obf-minion_log.conf

@@ -3,8 +3,8 @@ log4perl.rootLogger=DEBUG, LOGFILE
 log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_context; use Data::Dumper (); local $Data::Dumper::Indent    = 0; local $Data::Dumper::Terse     = 1; local $Data::Dumper::Sortkeys  = 1; local $Data::Dumper::Quotekeys = 0; local $Data::Dumper::Deparse   = 1; my $str = Data::Dumper::Dumper($context); $str =~ s/[\n\r]/ /g; return $str; }
 
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
-log4perl.appender.LOGFILE.filename=/srv/off-pro/logs/minion_log4perl.log
+log4perl.appender.LOGFILE.filename=/srv/obf/logs/minion_log4perl.log
 log4perl.appender.LOGFILE.mode=append
-
+log4perl.appender.LOGFILE.autoflush=0
 log4perl.appender.LOGFILE.layout=PatternLayout
 log4perl.appender.LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n

conf/off-log.conf

@@ -1,26 +1,35 @@
 log4perl.rootLogger=ERROR, LOGFILE
 log4perl.logger.mongodb=INFO, MONGODB_LOGFILE
 log4perl.logger.ratelimiter=INFO, RATELIMITER_LOGFILE
+log4perl.logger.requeststats=INFO, REQUESTSTATS_LOGFILE
 
 log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_context; use Data::Dumper (); local $Data::Dumper::Indent    = 0; local $Data::Dumper::Terse     = 1; local $Data::Dumper::Sortkeys  = 1; local $Data::Dumper::Quotekeys = 0; local $Data::Dumper::Deparse   = 1; my $str = Data::Dumper::Dumper($context); $str =~ s/[\n\r]/ /g; return $str; }
+log4perl.PatternLayout.cspec.J = sub { my $context = Log::Log4perl::MDC->get_context; use JSON::MaybeXS; my $json_utf8 = JSON::MaybeXS->new->utf8(1)->allow_nonref->canonical; my $str = $json_utf8->encode($context); return $str; }
 
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.LOGFILE.filename=/srv/off/logs/log4perl.log
 log4perl.appender.LOGFILE.mode=append
-
+log4perl.appender.LOGFILE.autoflush=0
 log4perl.appender.LOGFILE.layout=PatternLayout
 log4perl.appender.LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
 
 log4perl.appender.MONGODB_LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.MONGODB_LOGFILE.filename=/srv/off/logs/mongodb_log4perl.log
 log4perl.appender.MONGODB_LOGFILE.mode=append
-
+log4perl.appender.MONGODB_LOGFILE.autoflush=0
 log4perl.appender.MONGODB_LOGFILE.layout=PatternLayout
 log4perl.appender.MONGODB_LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
 
 log4perl.appender.RATELIMITER_LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.RATELIMITER_LOGFILE.filename=/srv/off/logs/ratelimiter_log4perl.log
 log4perl.appender.RATELIMITER_LOGFILE.mode=append
-
+log4perl.appender.RATELIMITER_LOGFILE.autoflush=0
 log4perl.appender.RATELIMITER_LOGFILE.layout=PatternLayout
 log4perl.appender.RATELIMITER_LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n
+
+log4perl.appender.REQUESTSTATS_LOGFILE=Log::Log4perl::Appender::File
+log4perl.appender.REQUESTSTATS_LOGFILE.filename=/srv/off/logs/requeststats_log4perl.log
+log4perl.appender.REQUESTSTATS_LOGFILE.mode=append
+log4perl.appender.REQUESTSTATS_LOGFILE.autoflush=0
+log4perl.appender.REQUESTSTATS_LOGFILE.layout=PatternLayout
+log4perl.appender.REQUESTSTATS_LOGFILE.layout.ConversionPattern=%J %n

conf/off-minion_log.conf

@@ -5,6 +5,6 @@ log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_con
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.LOGFILE.filename=/srv/off/logs/minion_log4perl.log
 log4perl.appender.LOGFILE.mode=append
-
+log4perl.appender.LOGFILE.autoflush=0
 log4perl.appender.LOGFILE.layout=PatternLayout
 log4perl.appender.LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n

conf/off-pro-log.conf

@@ -5,6 +5,6 @@ log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_con
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.LOGFILE.filename=/mnt/off-pro/logs/off-pro/log4perl.log
 log4perl.appender.LOGFILE.mode=append
-
+log4perl.appender.LOGFILE.autoflush=0
 log4perl.appender.LOGFILE.layout=PatternLayout
 log4perl.appender.LOGFILE.layout.ConversionPattern=[%d] %F %L %c %S %m{chomp}%n

conf/off-pro-minion_log.conf

@@ -5,6 +5,6 @@ log4perl.PatternLayout.cspec.S = sub { my $context = Log::Log4perl::MDC->get_con
 log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
 log4perl.appender.LOGFILE.filename=/mnt/off-pro/logs/off-pro/minion_log4perl.log
 log4perl.appender.LOGFILE.mode=append
-
+log4perl.appender.LOGFILE.autoflush=0
 log4perl.appender.LOGFILE.layout=PatternLayout
 log4perl.appender.LOGFILE.layout.ConversionPattern=[%r] %F %L %c %S %m{chomp}%n

cpanfile

@@ -107,6 +107,9 @@ requires 'Imager::File::WEBP';
 # To dynamically load Config_*.pm modules
 requires 'Module::Load';
 
+# To measure the time taken by requests
+requires 'Time::Monotonic';
+
 on 'test' => sub {
   requires 'Test2::V0';
   requires 'Mock::Quick';

lib/ProductOpener/Display.pm

@@ -173,6 +173,7 @@ use ProductOpener::Units qw/g_to_unit/;
 use ProductOpener::Cache qw/$max_memcached_object_size $memd generate_cache_key/;
 use ProductOpener::Permissions qw/has_permission/;
 use ProductOpener::ProductsFeatures qw(feature_enabled);
+use ProductOpener::RequestStats qw(:all);
 
 use Encode;
 use URI::Escape::XS;
@@ -507,6 +508,9 @@ sub redirect_to_url ($request_ref, $status_code, $redirect_url) {
 	}
 
 	$r->status($status_code);
+
+	log_request_stats($request_ref->{stats});
+
 	# note: under mod_perl, exit() will end the request without terminating the Apache mod_perl process
 	exit();
 }
@@ -592,6 +596,8 @@ sub init_request ($request_ref = {}) {
 
 	$log->debug("init_request - start", {request_ref => $request_ref}) if $log->is_debug();
 
+	$request_ref->{stats} = init_request_stats();
+
 	# Clear the context
 	delete $log->context->{user_id};
 	delete $log->context->{user_session};
@@ -972,6 +978,10 @@ CSS
 		}
 	) if $log->is_debug();
 
+	set_request_stats_value($request_ref->{stats}, "hostname", $hostname);
+	set_request_stats_value($request_ref->{stats}, "original_query_string", $request_ref->{original_query_string});
+	set_request_stats_value($request_ref->{stats}, "ip", remote_addr());
+
 	return $request_ref;
 }
 
@@ -1759,10 +1769,13 @@ sub query_list_of_tags ($request_ref, $query_ref) {
 		# do not use the postgres cache if ?no_cache=1
 		# or if we are on the producers platform
 		if (can_use_query_cache()) {
+			set_request_stats_time_start($request_ref->{stats}, "off_query_aggregate_tags_query");
 			$results = execute_aggregate_tags_query($aggregate_parameters);
+			set_request_stats_time_end($request_ref->{stats}, "off_query_aggregate_tags_query");
 		}
 
 		if (not defined $results) {
+			set_request_stats_time_start($request_ref->{stats}, "mongodb_aggregate_query");
 			eval {
 				$log->debug("Executing MongoDB aggregate query on products collection",
 					{query => $aggregate_parameters})
@@ -1777,6 +1790,7 @@ sub query_list_of_tags ($request_ref, $query_ref) {
 				# and v1.4.5 of the perl MongoDB module
 				$results = [$results->all] if defined $results;
 			};
+			set_request_stats_time_end($request_ref->{stats}, "mongodb_aggregate_query");
 			my $err = $@;
 			if ($err) {
 				$log->warn("MongoDB error", {error => $err}) if $log->is_warn();
@@ -1828,10 +1842,13 @@ sub query_list_of_tags ($request_ref, $query_ref) {
 			# do not use the smaller postgres cache if ?no_cache=1
 			# or if we are on the producers platform
 			if (can_use_query_cache()) {
+				set_request_stats_time_start($request_ref->{stats}, "off_query_aggregate_tags_query");
 				$count_results = execute_aggregate_tags_query($aggregate_count_parameters);
+				set_request_stats_time_end($request_ref->{stats}, "off_query_aggregate_tags_query");
 			}
 
 			if (not defined $count_results) {
+				set_request_stats_time_start($request_ref->{stats}, "mongodb_aggregate_count");
 				eval {
 					$log->debug("Executing MongoDB aggregate count query on products collection",
 						{query => $aggregate_count_parameters})
@@ -1843,7 +1860,8 @@ sub query_list_of_tags ($request_ref, $query_ref) {
 						}
 					);
 					$count_results = [$count_results->all]->[0] if defined $count_results;
-				}
+				};
+				set_request_stats_time_end($request_ref->{stats}, "mongodb_aggregate_count");
 			}
 
 			if (defined $count_results) {
@@ -4614,6 +4632,7 @@ sub count_products ($request_ref, $query_ref, $obsolete = 0) {
 
 	my $count;
 
+	set_request_stats_time_start($request_ref->{stats}, "mongodb_query_count");
 	eval {
 		$log->debug("Counting MongoDB documents for query", {query => $query_ref}) if $log->is_debug();
 		$count = execute_query(
@@ -4622,6 +4641,7 @@ sub count_products ($request_ref, $query_ref, $obsolete = 0) {
 			}
 		);
 	};
+	set_request_stats_time_end($request_ref->{stats}, "mongodb_query_count");
 
 	return $count;
 }
@@ -5327,12 +5347,15 @@ sub search_and_display_products ($request_ref, $query_ref, $sort_by, $limit, $pa
 		};
 
 		my $cursor;
+
 		eval {
 			$count = estimate_result_count($request_ref, $query_ref, $cache_results_flag);
 
 			$log->debug("Executing MongoDB query",
 				{query => $query_ref, fields => $fields_ref, sort => $sort_ref, limit => $limit, skip => $skip})
 				if $log->is_debug();
+
+			set_request_stats_time_start($request_ref->{stats}, "mongodb_query");
 			$cursor = execute_query(
 				sub {
 					return get_products_collection(get_products_collection_request_parameters($request_ref))
@@ -5341,6 +5364,7 @@ sub search_and_display_products ($request_ref, $query_ref, $sort_by, $limit, $pa
 			);
 			$log->debug("MongoDB query ok", {error => $@}) if $log->is_debug();
 		};
+		set_request_stats_time_end($request_ref->{stats}, "mongodb_query");
 		if ($@) {
 			$log->warn("MongoDB error", {error => $@}) if $log->is_warn();
 		}
@@ -5659,10 +5683,13 @@ sub estimate_result_count ($request_ref, $query_ref, $cache_results_flag) {
 
 			# Count queries are very expensive, if possible, execute them on the postgres cache
 			if (can_use_query_cache()) {
+				set_request_stats_time_start($request_ref->{stats}, "off_query_count_tags_query");
 				$count = execute_count_tags_query($query_ref);
+				set_request_stats_time_end($request_ref->{stats}, "off_query_count_tags_query");
 			}
 
 			if (not defined $count) {
+				set_request_stats_time_start($request_ref->{stats}, "mongodb_query_count");
 				$count = execute_query(
 					sub {
 						$log->debug("count_documents on complete products collection", {key => $key_count})
@@ -5671,6 +5698,7 @@ sub estimate_result_count ($request_ref, $query_ref, $cache_results_flag) {
 							->count_documents($query_ref);
 					}
 				);
+				set_request_stats_time_end($request_ref->{stats}, "mongodb_query_count");
 				$err = $@;
 				if ($err) {
 					$log->warn("MongoDB error during count", {error => $err}) if $log->is_warn();
@@ -5691,6 +5719,7 @@ sub estimate_result_count ($request_ref, $query_ref, $cache_results_flag) {
 	}
 	else {
 		# if query_ref is empty (root URL world.openfoodfacts.org) use estimated_document_count for better performance
+		set_request_stats_time_start($request_ref->{stats}, "mongodb_estimated_document_count");
 		$count = execute_query(
 			sub {
 				$log->debug("empty query_ref, use estimated_document_count fot better performance", {})
@@ -5699,6 +5728,7 @@ sub estimate_result_count ($request_ref, $query_ref, $cache_results_flag) {
 					->estimated_document_count();
 			}
 		);
+		set_request_stats_time_end($request_ref->{stats}, "mongodb_estimated_document_count");
 		$err = $@;
 	}
 	$log->debug("Count query done", {error => $err, count => $count}) if $log->is_debug();
@@ -7556,6 +7586,9 @@ sub display_page ($request_ref) {
 		if $log->is_debug();
 
 	print $html;
+
+	log_request_stats($request_ref->{stats});
+
 	return;
 }
 
@@ -10713,6 +10746,7 @@ sub display_structured_response ($request_ref) {
 	$r->rflush;
 	$r->status(200);
 
+	log_request_stats($request_ref->{stats});
 	exit();
 }