diff -r 5e51c5545029 src/auth/auth-request-handler.c
--- a/src/auth/auth-request-handler.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/auth/auth-request-handler.c	Tue Jun 18 16:26:00 2013 +0300
@@ -10,6 +10,7 @@
 #include "str.h"
 #include "strescape.h"
 #include "str-sanitize.h"
+#include "time-util.h"
 #include "master-interface.h"
 #include "auth-penalty.h"
 #include "auth-request.h"
@@ -259,6 +260,15 @@
 		   process to pick it up. delete it */
 		auth_request_handler_remove(handler, request);
 	}
+	int msecs = timeval_diff_msecs(&ioloop_timeval, &request->last_reply);
+	if (msecs > 500) {
+		auth_request_log_warning(request, "auth",
+			"Auth request took %d ms: last_reply=%d pre_passdb=%d post_passdb=%d",
+			timeval_diff_msecs(&ioloop_timeval, &request->created),
+			timeval_diff_msecs(&request->last_reply, &request->created),
+			timeval_diff_msecs(&request->pre_passdb, &request->created),
+			timeval_diff_msecs(&request->post_passdb, &request->created));
+	}
 	handler->callback(str_c(str), handler->context);
 }
 
@@ -622,6 +632,7 @@
         struct auth_request_handler *handler = request->handler;
 	string_t *str;
 	const char *value;
+	int msecs;
 
 	i_assert(request->state == AUTH_REQUEST_STATE_USERDB);
 
@@ -674,6 +685,17 @@
 		}
 		break;
 	}
+
+	msecs = timeval_diff_msecs(&ioloop_timeval, &request->last_reply);
+	if (msecs > 500) {
+		auth_request_log_warning(request, "auth",
+			"Auth login took %d ms: last_reply=%d pre_passdb=%d post_passdb=%d pre_userdb=%d",
+			timeval_diff_msecs(&ioloop_timeval, &request->created),
+			timeval_diff_msecs(&request->last_reply, &request->created),
+			timeval_diff_msecs(&request->pre_passdb, &request->created),
+			timeval_diff_msecs(&request->post_passdb, &request->created),
+			timeval_diff_msecs(&request->pre_userdb, &request->created));
+	}
 	handler->master_callback(str_c(str), request->master);
 
 	auth_master_connection_unref(&request->master);
diff -r 5e51c5545029 src/auth/auth-request.c
--- a/src/auth/auth-request.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/auth/auth-request.c	Tue Jun 18 16:26:00 2013 +0300
@@ -57,6 +57,7 @@
 
 	request->refcount = 1;
 	request->last_access = ioloop_time;
+	request->created = request->last_reply = ioloop_timeval;
 	request->session_pid = (pid_t)-1;
 
 	request->set = global_auth_settings;
@@ -80,6 +81,7 @@
 
 	request->refcount = 1;
 	request->last_access = ioloop_time;
+	request->created = request->last_reply = ioloop_timeval;
 	request->session_pid = (pid_t)-1;
 	request->set = global_auth_settings;
 	request->extra_fields = auth_fields_init(request->pool);
@@ -378,6 +380,8 @@
 {
 	i_assert(request->state == AUTH_REQUEST_STATE_MECH_CONTINUE);
 
+	request->last_reply = ioloop_timeval;
+
 	if (request->successful) {
 		auth_request_success(request, "", 0);
 		return;
@@ -644,6 +648,7 @@
 		auth_request_verify_plain(request, request->mech_password,
 			request->private_callback.verify_plain);
 	} else {
+		request->post_passdb = ioloop_timeval;
 		auth_request_ref(request);
 		request->passdb_result = result;
 		request->private_callback.verify_plain(result, request);
@@ -738,6 +743,7 @@
 		request->mech_password = p_strdup(request->pool, password);
 	else
 		i_assert(request->mech_password == password);
+	request->pre_passdb = ioloop_timeval;
 	request->private_callback.verify_plain = callback;
 
 	cache_key = passdb_cache == NULL ? NULL : passdb->cache_key;
@@ -788,6 +794,7 @@
 			   but the user was unknown there */
 			result = PASSDB_RESULT_USER_UNKNOWN;
 		}
+		request->post_passdb = ioloop_timeval;
 		request->passdb_result = result;
 		request->private_callback.
 			lookup_credentials(result, credentials, size, request);
@@ -848,6 +855,7 @@
 	}
 	passdb = request->passdb->passdb;
 
+	request->pre_passdb = ioloop_timeval;
 	request->credentials_scheme = p_strdup(request->pool, scheme);
 	request->private_callback.lookup_credentials = callback;
 
@@ -1036,6 +1044,7 @@
 	struct userdb_module *userdb = request->userdb->userdb;
 	const char *cache_key;
 
+	request->pre_userdb = ioloop_timeval;
 	request->private_callback.userdb = callback;
 	request->userdb_lookup = TRUE;
 
diff -r 5e51c5545029 src/auth/auth-request.h
--- a/src/auth/auth-request.h	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/auth/auth-request.h	Tue Jun 18 16:26:00 2013 +0300
@@ -6,6 +6,7 @@
 #include "mech.h"
 #include "userdb.h"
 #include "passdb.h"
+#include <sys/time.h>
 
 struct auth_client_connection;
 
@@ -72,6 +73,8 @@
 	time_t last_access;
 	pid_t session_pid;
 
+	struct timeval created, last_reply, pre_passdb, post_passdb, pre_userdb;
+
 	const char *service, *mech_name, *session_id;
 	struct ip_addr local_ip, remote_ip, real_local_ip, real_remote_ip;
 	unsigned int local_port, remote_port, real_local_port, real_remote_port;
diff -r 5e51c5545029 src/imap-login/imap-proxy.c
--- a/src/imap-login/imap-proxy.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/imap-login/imap-proxy.c	Tue Jun 18 16:26:00 2013 +0300
@@ -87,6 +87,7 @@
 		sasl_client_new(client->common.proxy_mech, &sasl_set);
 	mech_name = sasl_client_mech_get_name(client->common.proxy_mech);
 
+	client->common.pre_proxy_auth = ioloop_timeval;
 	str_append(str, "L AUTHENTICATE ");
 	str_append(str, mech_name);
 	if (client->proxy_sasl_ir) {
@@ -199,6 +200,7 @@
 	output = login_proxy_get_ostream(client->login_proxy);
 	if (!imap_client->proxy_seen_banner) {
 		/* this is a banner */
+		client->proxy_banner = ioloop_timeval;
 		client->proxy_state = IMAP_PROXY_STATE_BANNER;
 		imap_client->proxy_seen_banner = TRUE;
 		if (proxy_input_banner(imap_client, output, line) < 0) {
@@ -269,6 +271,7 @@
 		return 1;
 	} else if (strncmp(line, "L OK ", 5) == 0) {
 		/* Login successful. Send this line to client. */
+		client->post_proxy_auth = ioloop_timeval;
 		client->proxy_state = IMAP_PROXY_STATE_LOGIN;
 		str = t_str_new(128);
 		client_send_login_reply(imap_client, str, line + 5);
diff -r 5e51c5545029 src/login-common/client-common-auth.c
--- a/src/login-common/client-common-auth.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/login-common/client-common-auth.c	Tue Jun 18 16:26:00 2013 +0300
@@ -362,6 +362,7 @@
 client_auth_handle_reply(struct client *client,
 			 const struct client_auth_reply *reply, bool success)
 {
+	client->post_auth = ioloop_timeval;
 	if (reply->proxy) {
 		/* we want to proxy the connection to another server.
 		   don't do this unless authentication succeeded. with
@@ -595,10 +596,13 @@
 		if (client->auth_response != NULL)
 			str_truncate(client->auth_response, 0);
 
+		if (client->first_auth_reply.tv_sec == 0)
+			client->first_auth_reply = ioloop_timeval;
 		i_assert(client->io == NULL);
 		client->auth_waiting = TRUE;
 		client->io = io_add(client->fd, IO_READ,
 				    client_auth_input, client);
+		client->last_auth_send = ioloop_timeval;
 		client_auth_input(client);
 		return;
 	}
@@ -623,6 +627,8 @@
 
 	client_ref(client);
 	client->auth_initializing = TRUE;
+	client->pre_auth = ioloop_timeval;
+	client->last_auth_send = ioloop_timeval;
 	sasl_server_auth_begin(client, login_binary->protocol, mech_name,
 			       init_resp, sasl_callback);
 	client->auth_initializing = FALSE;
diff -r 5e51c5545029 src/login-common/client-common.c
--- a/src/login-common/client-common.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/login-common/client-common.c	Tue Jun 18 16:26:00 2013 +0300
@@ -119,6 +119,7 @@
 		client->v.auth_parse_response = client_auth_parse_response;
 
 	client->created = ioloop_time;
+	client->created_tv = ioloop_timeval;
 	client->refcount = 1;
 
 	client->pool = pool;
diff -r 5e51c5545029 src/login-common/client-common.h
--- a/src/login-common/client-common.h	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/login-common/client-common.h	Tue Jun 18 16:26:00 2013 +0300
@@ -100,6 +100,8 @@
 	time_t created;
 	int refcount;
 
+	struct timeval created_tv, proxy_banner, pre_auth, first_auth_reply, last_auth_send, post_auth, pre_proxy_connect, post_proxy_connect, pre_proxy_auth, post_proxy_auth;
+
 	struct ip_addr local_ip;
 	struct ip_addr ip;
 	struct ip_addr real_remote_ip, real_local_ip;
diff -r 5e51c5545029 src/login-common/login-proxy.c
--- a/src/login-common/login-proxy.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/login-common/login-proxy.c	Tue Jun 18 16:26:00 2013 +0300
@@ -238,6 +238,7 @@
 	proxy->state_rec->last_success = ioloop_timeval;
 	proxy->state_rec->num_waiting_connections--;
 	proxy->state_rec = NULL;
+	proxy->client->post_proxy_connect = ioloop_timeval;
 
 	if ((proxy->ssl_flags & PROXY_SSL_FLAG_YES) != 0 &&
 	    (proxy->ssl_flags & PROXY_SSL_FLAG_STARTTLS) == 0) {
@@ -323,6 +324,7 @@
 	proxy->connect_timeout_msecs = set->connect_timeout_msecs;
 	proxy->notify_refresh_secs = set->notify_refresh_secs;
 	proxy->ssl_flags = set->ssl_flags;
+	client->pre_proxy_connect = ioloop_timeval;
 	client_ref(client);
 
 	if (set->ip.family == 0 &&
@@ -462,6 +464,25 @@
 	login_proxy_state_notify(proxy_state, proxy->client->proxy_user);
 }
 
+static void warn_long_login(struct client *client)
+{
+	int msecs = timeval_diff_msecs(&ioloop_timeval, &client->pre_auth);
+
+	if (msecs < 1000)
+		return;
+	client_log_warn(client, t_strdup_printf("client login took %u ms: pre_auth=%d first_auth_reply=%d post_auth=%d pre_proxy_connect=%d post_proxy_connect=%d pre_proxy_auth=%d post_proxy_auth=%d banner=%d",
+		  timeval_diff_msecs(&ioloop_timeval, &client->created_tv),
+		  timeval_diff_msecs(&client->pre_auth, &client->created_tv),
+		  client->first_auth_reply.tv_sec == 0 ? -1 :
+		  timeval_diff_msecs(&client->first_auth_reply, &client->created_tv),
+		  timeval_diff_msecs(&client->post_auth, &client->created_tv),
+		  timeval_diff_msecs(&client->pre_proxy_connect, &client->created_tv),
+		  timeval_diff_msecs(&client->post_proxy_connect, &client->created_tv),
+		  timeval_diff_msecs(&client->pre_proxy_auth, &client->created_tv),
+		  timeval_diff_msecs(&client->post_proxy_auth, &client->created_tv),
+		  timeval_diff_msecs(&client->proxy_banner, &client->created_tv)));
+}
+
 void login_proxy_detach(struct login_proxy *proxy)
 {
 	struct client *client = proxy->client;
@@ -471,6 +492,8 @@
 	i_assert(proxy->client_fd == -1);
 	i_assert(proxy->server_output != NULL);
 
+	warn_long_login(proxy->client);
+
 	if (proxy->to != NULL)
 		timeout_remove(&proxy->to);
 
diff -r 5e51c5545029 src/pop3-login/pop3-proxy.c
--- a/src/pop3-login/pop3-proxy.c	Tue Jun 18 15:14:42 2013 +0300
+++ b/src/pop3-login/pop3-proxy.c	Tue Jun 18 16:26:00 2013 +0300
@@ -43,6 +43,7 @@
 		client->common.proxy_state = POP3_PROXY_LOGIN1;
 	}
 
+	client->common.pre_proxy_auth = ioloop_timeval;
 	str = t_str_new(128);
 	if (client->common.proxy_mech == NULL) {
 		/* send USER command */
@@ -133,6 +134,7 @@
 	switch (client->proxy_state) {
 	case POP3_PROXY_BANNER:
 		/* this is a banner */
+		client->proxy_banner = ioloop_timeval;
 		if (strncmp(line, "+OK", 3) != 0) {
 			client_log_err(client, t_strdup_printf(
 				"proxy: Remote returned invalid banner: %s",
@@ -208,6 +210,7 @@
 		}
 		if (strncmp(line, "+OK", 3) != 0)
 			break;
+		client->post_proxy_auth = ioloop_timeval;
 
 		/* Login successful. Send this line to client. */
 		line = t_strconcat(line, "\r\n", NULL);
