diff -r 58cb2c6f90c7 src/imap/client.c
--- a/src/imap/client.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/client.c	Fri Jan 11 02:48:19 2008 +0200
@@ -70,7 +70,12 @@ void client_command_cancel(struct client
 	bool cmd_ret;
 
 	cmd->cancel = TRUE;
+	i_debug("cmd cancel: tag=%s name=%s box=%s",
+		cmd->tag, cmd->name, cmd->client->mailbox == NULL ? "" :
+		mailbox_get_name(cmd->client->mailbox));
 	cmd_ret = cmd->func == NULL ? TRUE : cmd->func(cmd);
+	i_debug("cmd cancel return: tag=%s name=%s finished=%d",
+		cmd->tag, cmd->name, cmd_ret);
 	if (!cmd_ret && !cmd->param_error) {
 		if (cmd->client->output->closed)
 			i_panic("command didn't cancel itself: %s", cmd->name);
@@ -537,10 +542,17 @@ static bool client_command_input(struct 
 static bool client_command_input(struct client_command_context *cmd)
 {
 	struct client *client = cmd->client;
+	bool finished;
 
         if (cmd->func != NULL) {
 		/* command is being executed - continue it */
-		if (cmd->func(cmd) || cmd->param_error) {
+		i_debug("cmd input: tag=%s name=%s box=%s",
+			cmd->tag, cmd->name, cmd->client->mailbox == NULL ? "" :
+			mailbox_get_name(cmd->client->mailbox));
+		finished = cmd->func(cmd) || cmd->param_error;
+		i_debug("cmd input return: tag=%s name=%s finished=%d",
+			cmd->tag, cmd->name, finished);
+		if (finished) {
 			/* command execution was finished */
 			client_command_free(cmd);
 			client_add_missing_io(client);
@@ -701,7 +713,12 @@ static void client_output_cmd(struct cli
 	bool finished;
 
 	/* continue processing command */
+	i_debug("cmd output: tag=%s name=%s box=%s",
+		cmd->tag, cmd->name, cmd->client->mailbox == NULL ? "" :
+		mailbox_get_name(cmd->client->mailbox));
 	finished = cmd->func(cmd) || cmd->param_error;
+	i_debug("cmd output return: tag=%s name=%s finished=%d",
+		cmd->tag, cmd->name, finished);
 
 	if (!finished)
 		(void)client_handle_unfinished_cmd(cmd);
diff -r 58cb2c6f90c7 src/imap/cmd-copy.c
--- a/src/imap/cmd-copy.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-copy.c	Fri Jan 11 02:48:19 2008 +0200
@@ -117,6 +117,8 @@ bool cmd_copy(struct client_command_cont
 	if (storage == NULL)
 		return TRUE;
 
+	i_debug("COPY: %s %s", messageset, mailbox);
+
 	if (mailbox_equals(client->mailbox, storage, mailbox))
 		destbox = client->mailbox;
 	else {
diff -r 58cb2c6f90c7 src/imap/cmd-fetch.c
--- a/src/imap/cmd-fetch.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-fetch.c	Fri Jan 11 02:48:19 2008 +0200
@@ -1,6 +1,8 @@
 /* Copyright (c) 2002-2008 Dovecot authors, see the included COPYING file */
 
 #include "common.h"
+#include "str.h"
+#include "strescape.h"
 #include "ostream.h"
 #include "commands.h"
 #include "imap-fetch.h"
@@ -145,6 +147,8 @@ bool cmd_fetch(struct client_command_con
 	if (ctx == NULL)
 		return TRUE;
 
+	i_debug("FETCH: %s", imap_args_to_str(args));
+
 	if (!fetch_parse_args(ctx, &args[1])) {
 		imap_fetch_deinit(ctx);
 		return TRUE;
diff -r 58cb2c6f90c7 src/imap/cmd-search.c
--- a/src/imap/cmd-search.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-search.c	Fri Jan 11 02:48:19 2008 +0200
@@ -162,6 +162,7 @@ bool cmd_search(struct client_command_co
 	if (!client_verify_open_mailbox(cmd))
 		return TRUE;
 
+	i_debug("SEARCH: %s", imap_args_to_str(args));
 	if (args->type == IMAP_ARG_ATOM &&
 	    strcasecmp(IMAP_ARG_STR_NONULL(args), "CHARSET") == 0) {
 		/* CHARSET specified */
diff -r 58cb2c6f90c7 src/imap/cmd-select.c
--- a/src/imap/cmd-select.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-select.c	Fri Jan 11 02:48:19 2008 +0200
@@ -79,6 +79,8 @@ bool cmd_select_full(struct client_comma
 	client_send_tagline(cmd, mailbox_is_readonly(box) ?
 			    "OK [READ-ONLY] Select completed." :
 			    "OK [READ-WRITE] Select completed.");
+	i_debug("SELECT: %s msgs=%u recent=%u unseen=%u", mailbox,
+		status.messages, status.recent, status.unseen);
 	return TRUE;
 }
 
diff -r 58cb2c6f90c7 src/imap/cmd-sort.c
--- a/src/imap/cmd-sort.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-sort.c	Fri Jan 11 02:48:19 2008 +0200
@@ -112,6 +112,7 @@ bool cmd_sort(struct client_command_cont
 		return TRUE;
 	}
 
+	i_debug("SORT: %s", imap_args_to_str(args));
 	if (get_sort_program(cmd, IMAP_ARG_LIST_ARGS(args), sorting) < 0)
 		return TRUE;
 	args++;
diff -r 58cb2c6f90c7 src/imap/cmd-status.c
--- a/src/imap/cmd-status.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-status.c	Fri Jan 11 02:48:19 2008 +0200
@@ -33,6 +33,7 @@ bool cmd_status(struct client_command_co
 	if (storage == NULL)
 		return TRUE;
 
+	i_debug("STATUS: %s", mailbox);
 	if (!imap_status_get(client, storage, real_mailbox, items, &status)) {
 		client_send_storage_error(cmd, storage);
 		return TRUE;
diff -r 58cb2c6f90c7 src/imap/cmd-store.c
--- a/src/imap/cmd-store.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-store.c	Fri Jan 11 02:48:19 2008 +0200
@@ -57,6 +57,8 @@ bool cmd_store(struct client_command_con
 
 	if (!client_verify_open_mailbox(cmd))
 		return TRUE;
+
+	i_debug("STORE: %s", imap_args_to_str(args));
 
 	/* validate arguments */
 	messageset = imap_arg_string(&args[0]);
diff -r 58cb2c6f90c7 src/imap/cmd-thread.c
--- a/src/imap/cmd-thread.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/cmd-thread.c	Fri Jan 11 02:48:19 2008 +0200
@@ -36,6 +36,7 @@ bool cmd_thread(struct client_command_co
 		return TRUE;
 	}
 
+	i_debug("THREAD: %s", imap_args_to_str(args));
 	str = IMAP_ARG_STR(args);
 	if (strcasecmp(str, "REFERENCES") == 0)
 		threading = MAIL_THREAD_REFERENCES;
diff -r 58cb2c6f90c7 src/imap/commands-util.c
--- a/src/imap/commands-util.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/commands-util.c	Fri Jan 11 02:48:19 2008 +0200
@@ -4,6 +4,7 @@
 #include "array.h"
 #include "buffer.h"
 #include "str.h"
+#include "strescape.h"
 #include "str-sanitize.h"
 #include "mail-storage.h"
 #include "commands-util.h"
@@ -368,3 +369,59 @@ void msgset_generator_finish(struct msgs
 	else
 		str_printfa(ctx->str, "%u:%u", ctx->first_uid, ctx->last_uid);
 }
+
+static void
+imap_args_to_str_dest(const struct imap_arg *args, string_t *str)
+{
+	const ARRAY_TYPE(imap_arg_list) *list;
+	bool first = TRUE;
+
+	for (; args->type != IMAP_ARG_EOL; args++) {
+		if (first)
+			first = FALSE;
+		else
+			str_append_c(str, ' ');
+
+		switch (args->type) {
+		case IMAP_ARG_NIL:
+			str_append(str, "NIL");
+			break;
+		case IMAP_ARG_ATOM:
+			str_append(str, IMAP_ARG_STR(args));
+			break;
+		case IMAP_ARG_STRING:
+			str_append_c(str, '"');
+			str_append(str, str_escape(IMAP_ARG_STR(args)));
+			str_append_c(str, '"');
+			break;
+		case IMAP_ARG_LITERAL: {
+			const char *strarg = IMAP_ARG_STR(args);
+			str_printfa(str, "{%"PRIuSIZE_T"}\r\n", strlen(strarg));
+			str_append(str, strarg);
+			break;
+		}
+		case IMAP_ARG_LIST:
+			str_append_c(str, '(');
+			list = IMAP_ARG_LIST(args);
+			imap_args_to_str_dest(array_idx(list, 0), str);
+			str_append_c(str, ')');
+			break;
+		case IMAP_ARG_LITERAL_SIZE:
+		case IMAP_ARG_LITERAL_SIZE_NONSYNC:
+		case IMAP_ARG_EOL:
+			i_unreached();
+		}
+	}
+}
+
+const char *imap_args_to_str(const struct imap_arg *args)
+{
+	string_t *str;
+
+	if (args == NULL)
+		return "";
+
+	str = t_str_new(256);
+	imap_args_to_str_dest(args, str);
+	return str_c(str);
+}
diff -r 58cb2c6f90c7 src/imap/commands-util.h
--- a/src/imap/commands-util.h	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/commands-util.h	Fri Jan 11 02:48:19 2008 +0200
@@ -68,4 +68,6 @@ void msgset_generator_next(struct msgset
 void msgset_generator_next(struct msgset_generator_context *ctx, uint32_t uid);
 void msgset_generator_finish(struct msgset_generator_context *ctx);
 
+const char *imap_args_to_str(const struct imap_arg *args);
+
 #endif
diff -r 58cb2c6f90c7 src/imap/imap-sync.c
--- a/src/imap/imap-sync.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/imap/imap-sync.c	Fri Jan 11 02:48:19 2008 +0200
@@ -44,6 +44,7 @@ imap_sync_init(struct client *client, st
 	ctx->box = box;
 	ctx->imap_flags = imap_flags;
 
+	i_debug("imap sync init: box=%s", mailbox_get_name(box));
 	ctx->sync_ctx = mailbox_sync_init(box, flags);
 	ctx->t = mailbox_transaction_begin(box, 0);
 	ctx->mail = mail_alloc(ctx->t, MAIL_FETCH_FLAGS, 0);
@@ -91,6 +92,8 @@ int imap_sync_deinit(struct imap_sync_co
 				t_strdup_printf("* %u RECENT", status.recent));
 		}
 	}
+	i_debug("imap sync deinit: box=%s",
+		mailbox_get_name(ctx->client->mailbox));
 
 	array_free(&ctx->tmp_keywords);
 	i_free(ctx);
diff -r 58cb2c6f90c7 src/lib-index/mail-cache-compress.c
--- a/src/lib-index/mail-cache-compress.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache-compress.c	Fri Jan 11 02:48:19 2008 +0200
@@ -20,6 +20,8 @@ struct mail_cache_copy_context {
 	ARRAY_DEFINE(bitmask_pos, unsigned int);
 	uint32_t *field_file_map;
 
+	unsigned int temp_drop_count, temp_drop_msg_count;
+
 	uint8_t field_seen_value;
 	bool new_msg;
 };
@@ -72,8 +74,10 @@ mail_cache_compress_field(struct mail_ca
 		if (dec == MAIL_CACHE_DECISION_NO)
 			return;
 	} else {
-		if (dec != MAIL_CACHE_DECISION_YES)
+		if (dec != MAIL_CACHE_DECISION_YES) {
+			ctx->temp_drop_count++;
 			return;
+		}
 	}
 
 	buffer_append(ctx->buffer, &file_field_idx, sizeof(file_field_idx));
@@ -163,7 +167,7 @@ mail_cache_copy(struct mail_cache *cache
 	struct mail_cache_record cache_rec;
 	struct ostream *output;
 	uint32_t message_count, seq, first_new_seq, ext_offset;
-	unsigned int i, used_fields_count, orig_fields_count;
+	unsigned int i, used_fields_count, orig_fields_count, orig_temp_drop_count;
 	time_t max_drop_time;
 
 	view = mail_index_transaction_get_view(trans);
@@ -190,10 +194,13 @@ mail_cache_copy(struct mail_cache *cache
 	idx_hdr = mail_index_get_header(view);
 	max_drop_time = idx_hdr->day_stamp == 0 ? 0 :
 		idx_hdr->day_stamp - MAIL_CACHE_FIELD_DROP_SECS;
+	i_debug("cache compression: day_stamp=%u -> max_drop_time=%u",
+		idx_hdr->day_stamp, (unsigned)max_drop_time);
 
 	orig_fields_count = cache->fields_count;
 	if (cache->file_fields_count == 0) {
 		/* creating the initial cache file. add all fields. */
+		i_debug("cache compression: Initial cache file, keeping all fields");
 		for (i = 0; i < orig_fields_count; i++)
 			ctx.field_file_map[i] = i;
 		used_fields_count = i;
@@ -203,6 +210,11 @@ mail_cache_copy(struct mail_cache *cache
 				&cache->fields[i];
 			enum mail_cache_decision_type dec =
 				field->field.decision;
+			bool orig_used = field->used;
+
+			i_debug("cache compression: field[%s]: used=%d, last_used=%u, dec=0x%x, adding=%d",
+				cache->fields[i].field.name, cache->fields[i].used,
+				cache->fields[i].last_used, dec, field->adding);
 
 			/* if the decision isn't forced and this field hasn't
 			   been accessed for a while, drop it */
@@ -219,6 +231,8 @@ mail_cache_copy(struct mail_cache *cache
 				field->used = FALSE;
 				field->last_used = 0;
 			}
+			if (orig_used != field->used)
+				i_debug("cache compression:  --> drop");
 
 			ctx.field_file_map[i] = !field->used ?
 				(uint32_t)-1 : used_fields_count++;
@@ -229,10 +243,13 @@ mail_cache_copy(struct mail_cache *cache
 	   removed. */
 	first_new_seq = mail_cache_get_first_new_seq(view);
 	message_count = mail_index_view_get_messages_count(view);
+	i_debug("cache compression: first_new_seq=%u, message_count=%u",
+		first_new_seq, message_count);
 
 	i_array_init(ext_offsets, message_count);
 	for (seq = 1; seq <= message_count; seq++) {
 		if (mail_index_transaction_is_expunged(trans, seq)) {
+			i_debug(" - dropping expunged seq=%u", seq);
 			(void)array_append_space(ext_offsets);
 			continue;
 		}
@@ -249,9 +266,12 @@ mail_cache_copy(struct mail_cache *cache
 		memset(&cache_rec, 0, sizeof(cache_rec));
 		buffer_append(ctx.buffer, &cache_rec, sizeof(cache_rec));
 
+		orig_temp_drop_count = ctx.temp_drop_count;
 		mail_cache_lookup_iter_init(cache_view, seq, &iter);
 		while (mail_cache_lookup_iter_next(&iter, &field) > 0)
 			mail_cache_compress_field(&ctx, &field);
+		if (orig_temp_drop_count != ctx.temp_drop_count)
+			ctx.temp_drop_msg_count++;
 
 		cache_rec.size = buffer_get_used_size(ctx.buffer);
 		if (cache_rec.size == sizeof(cache_rec)) {
@@ -294,6 +314,7 @@ mail_cache_copy(struct mail_cache *cache
 		(void)file_set_size(fd, MAIL_CACHE_INITIAL_SIZE);
 	}
 
+	i_debug("cache compressed: %u bytes", hdr.used_file_size);
 	o_stream_destroy(&output);
 
 	if (cache->index->nfs_flush) {
diff -r 58cb2c6f90c7 src/lib-index/mail-cache-fields.c
--- a/src/lib-index/mail-cache-fields.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache-fields.c	Fri Jan 11 02:48:19 2008 +0200
@@ -229,8 +229,11 @@ static int mail_cache_header_fields_get_
 	}
 	cache->last_field_header_offset = offset;
 
-	if (next_count > MAIL_CACHE_HEADER_FIELD_CONTINUE_COUNT)
+	if (next_count > MAIL_CACHE_HEADER_FIELD_CONTINUE_COUNT) {
+		i_debug("cache compress want: too many field headers (%u > %u)",
+			next_count, MAIL_CACHE_HEADER_FIELD_CONTINUE_COUNT);
 		cache->need_compress_file_seq = cache->hdr->file_seq;
+	}
 
 	if (map) {
 		if (cache->file_cache != NULL && invalidate) {
@@ -375,6 +378,9 @@ int mail_cache_header_fields_read(struct
 		    dec != MAIL_CACHE_DECISION_NO) {
 			/* time to drop this field. don't bother dropping
 			   fields that have never been used. */
+			i_debug("cache compress want: drop field %s (last_used=%u, max_drop_time=%ld, dec=0x%x)",
+				cache->fields[fidx].field.name,
+				cache->fields[fidx].last_used, (long)max_drop_time, dec);
 			cache->need_compress_file_seq = cache->hdr->file_seq;
 		}
 
diff -r 58cb2c6f90c7 src/lib-index/mail-cache-private.h
--- a/src/lib-index/mail-cache-private.h	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache-private.h	Fri Jan 11 02:48:19 2008 +0200
@@ -146,6 +146,9 @@ struct mail_cache {
 	struct dotlock *dotlock;
 	struct file_lock *file_lock;
 
+	uoff_t write_size_count;
+	unsigned int write_count;
+
 	/* mmap_disable=no: hdr points to data / NULL when cache is invalid.
 	   mmap_disable=yes: hdr points to hdr_ro_copy. this is needed because
 	   cache invalidation can zero the data any time */
@@ -274,5 +277,6 @@ void mail_cache_sync_lost_handler(struct
 
 void mail_cache_set_syscall_error(struct mail_cache *cache,
 				  const char *function);
+void mail_cache_write_log(struct mail_cache *cache, const char *name);
 
 #endif
diff -r 58cb2c6f90c7 src/lib-index/mail-cache-sync-update.c
--- a/src/lib-index/mail-cache-sync-update.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache-sync-update.c	Fri Jan 11 02:48:19 2008 +0200
@@ -20,6 +20,7 @@ static void mail_cache_handler_deinit(st
 	if (ctx == NULL)
 		return;
 
+	mail_cache_write_log(sync_ctx->view->index->cache, "sync");
 	if (ctx->locked)
 		(void)mail_cache_unlock(sync_ctx->view->index->cache);
 	i_free(ctx);
@@ -56,6 +57,7 @@ static int mail_cache_handler_lock(struc
 		}
 		ctx->locked = TRUE;
 	}
+	mail_cache_write_log(cache, "unknown");
 	return 1;
 }
 
@@ -185,5 +187,6 @@ void mail_cache_sync_lost_handler(struct
 		mail_index_flush_read_cache(cache->index, cache->filepath,
 					    cache->fd, cache->locked);
 	}
+	i_debug("cache: sync lost, invalidating everything");
 	file_cache_invalidate(cache->file_cache, 0, (uoff_t)-1);
 }
diff -r 58cb2c6f90c7 src/lib-index/mail-cache-transaction.c
--- a/src/lib-index/mail-cache-transaction.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache-transaction.c	Fri Jan 11 02:48:19 2008 +0200
@@ -70,6 +70,7 @@ mail_cache_get_transaction(struct mail_c
 
 static void mail_cache_transaction_reset(struct mail_cache_transaction_ctx *ctx)
 {
+	i_debug("cache transaction reset");
 	ctx->cache_file_seq = MAIL_CACHE_IS_UNUSABLE(ctx->cache) ? 0 :
 		ctx->cache->hdr->file_seq;
 	mail_index_ext_set_reset_id(ctx->trans, ctx->cache->ext_id,
@@ -609,6 +610,9 @@ mail_cache_transaction_flush(struct mail
 		return 0;
 	}
 
+	mail_cache_write_log(cache, "unknown");
+	i_debug("cache flush");
+
 	rec = buffer_get_data(ctx->cache_data, &size);
 	i_assert(ctx->prev_pos <= size);
 
@@ -654,6 +658,7 @@ mail_cache_transaction_flush(struct mail
 		rec_pos += write_size;
 		rec = CONST_PTR_OFFSET(rec, write_size);
 	}
+	mail_cache_write_log(cache, "flush");
 
 	/* drop the written data from buffer */
 	buffer_copy(ctx->cache_data, 0,
@@ -781,6 +786,7 @@ mail_cache_header_fields_write(struct ma
 					     &offset, NULL, TRUE) <= 0)
 		return -1;
 
+	mail_cache_write_log(cache, "unknown");
 	if (mail_cache_write(cache, buffer->data, size, offset) < 0)
 		return -1;
 
@@ -802,6 +808,7 @@ mail_cache_header_fields_write(struct ma
 	offset = mail_index_uint32_to_offset(offset);
 	if (mail_cache_write(cache, &offset, sizeof(offset), hdr_offset) < 0)
 		return -1;
+	mail_cache_write_log(cache, "header fields");
 
 	if (hdr_offset == offsetof(struct mail_cache_header,
 				   field_header_offset)) {
@@ -889,7 +896,7 @@ void mail_cache_add(struct mail_cache_tr
 void mail_cache_add(struct mail_cache_transaction_ctx *ctx, uint32_t seq,
 		    unsigned int field_idx, const void *data, size_t data_size)
 {
-	uint32_t file_field, data_size32;
+	uint32_t file_field, data_size32, uid;
 	unsigned int fixed_size;
 	size_t full_size;
 	int ret;
@@ -901,6 +908,9 @@ void mail_cache_add(struct mail_cache_tr
 	    (MAIL_CACHE_DECISION_NO | MAIL_CACHE_DECISION_FORCED))
 		return;
 
+	mail_index_lookup_uid(ctx->view->view, seq, &uid);
+	i_debug("cache add: uid=%u name=%s",
+		uid, ctx->cache->fields[field_idx].field.name);
 	if (ctx->cache_file_seq == 0) {
 		mail_cache_transaction_open_if_needed(ctx);
 		if (!MAIL_CACHE_IS_UNUSABLE(ctx->cache))
@@ -1027,6 +1037,7 @@ static int mail_cache_link_unlocked(stru
 static int mail_cache_link_unlocked(struct mail_cache *cache,
 				    uint32_t old_offset, uint32_t new_offset)
 {
+	i_debug("cache link: %u -> %u", new_offset, old_offset);
 	new_offset += offsetof(struct mail_cache_record, prev_offset);
 	return mail_cache_write(cache, &old_offset, sizeof(old_offset),
 				new_offset);
diff -r 58cb2c6f90c7 src/lib-index/mail-cache.c
--- a/src/lib-index/mail-cache.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache.c	Fri Jan 11 02:48:19 2008 +0200
@@ -178,6 +178,8 @@ int mail_cache_reopen(struct mail_cache 
 		   file_seq really is corrupted. either way, this shouldn't
 		   happen often so we'll just mark cache to be compressed
 		   later which fixes this. */
+		i_debug("cache compress want: file is lost (file_seq=%u != reset_id=%u)",
+			cache->hdr->file_seq, ext->reset_id);
 		cache->need_compress_file_seq = cache->hdr->file_seq;
 		mail_index_view_close(&view);
 		return 0;
@@ -235,6 +237,12 @@ static bool mail_cache_verify_header(str
 		return FALSE;
 	}
 	return TRUE;
+}
+
+void mail_cache_read_log(struct mail_cache *cache, const char *name)
+{
+	if (cache->file_cache != NULL)
+		file_cache_read_log(cache->file_cache, name);
 }
 
 int mail_cache_map(struct mail_cache *cache, size_t offset, size_t size)
@@ -551,6 +559,7 @@ int mail_cache_lock(struct mail_cache *c
 		ret = 0;
 	}
 
+	i_debug("cache lock: %s", cache->filepath);
 	if (ret > 0) {
 		/* make sure our header is up to date */
 		if (cache->file_cache != NULL) {
@@ -581,6 +590,9 @@ static void mail_cache_update_need_compr
 	if (cont_percentage >= MAIL_CACHE_COMPRESS_CONTINUED_PERCENTAGE &&
 	    hdr->used_file_size >= MAIL_CACHE_COMPRESS_MIN_SIZE) {
 		/* too many continued rows, compress */
+		i_debug("cache compress want: too many continued rows (%u / %u)",
+			hdr->continued_record_count,
+			cache->index->map->rec_map->records_count);
 		cache->need_compress_file_seq = hdr->file_seq;
 	}
 
@@ -588,8 +600,11 @@ static void mail_cache_update_need_compr
 	max_del_space = hdr->used_file_size / 100 *
 		MAIL_CACHE_COMPRESS_PERCENTAGE;
 	if (hdr->deleted_space >= max_del_space &&
-	    hdr->used_file_size >= MAIL_CACHE_COMPRESS_MIN_SIZE)
+	    hdr->used_file_size >= MAIL_CACHE_COMPRESS_MIN_SIZE) {
+		i_debug("cache compress want: max deleted space (%u / %u)",
+			hdr->deleted_space, hdr->used_file_size);
 		cache->need_compress_file_seq = hdr->file_seq;
+	}
 }
 
 int mail_cache_unlock(struct mail_cache *cache)
@@ -618,6 +633,7 @@ int mail_cache_unlock(struct mail_cache 
 		mail_cache_update_need_compress(cache);
 	}
 
+	i_debug("cache unlock: %s (%d)", cache->filepath, cache->index->nfs_flush);
 	if (cache->index->nfs_flush) {
 		if (fdatasync(cache->fd) < 0)
 			mail_cache_set_syscall_error(cache, "fdatasync()");
@@ -627,9 +643,22 @@ int mail_cache_unlock(struct mail_cache 
 	return ret;
 }
 
+void mail_cache_write_log(struct mail_cache *cache, const char *name)
+{
+	if (cache->write_count > 0) {
+		i_debug("cache writes to %s: %u times, %"PRIuUOFF_T" bytes",
+			name, cache->write_count, cache->write_size_count);
+	}
+	cache->write_size_count = 0;
+	cache->write_count = 0;
+}
+
 int mail_cache_write(struct mail_cache *cache, const void *data, size_t size,
 		     uoff_t offset)
 {
+	cache->write_size_count += size;
+	cache->write_count++;
+
 	if (pwrite_full(cache->fd, data, size, offset) < 0) {
 		mail_cache_set_syscall_error(cache, "pwrite_full()");
 		return -1;
diff -r 58cb2c6f90c7 src/lib-index/mail-cache.h
--- a/src/lib-index/mail-cache.h	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-cache.h	Fri Jan 11 02:48:19 2008 +0200
@@ -110,4 +110,6 @@ void mail_cache_set_corrupted(struct mai
 void mail_cache_set_corrupted(struct mail_cache *cache, const char *fmt, ...)
 	ATTR_FORMAT(2, 3);
 
+void mail_cache_read_log(struct mail_cache *cache, const char *name);
+
 #endif
diff -r 58cb2c6f90c7 src/lib-index/mail-index-write.c
--- a/src/lib-index/mail-index-write.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-index-write.c	Fri Jan 11 02:48:19 2008 +0200
@@ -42,6 +42,7 @@ static int mail_index_recreate(struct ma
 		mail_index_file_set_syscall_error(index, path, "write()");
 		ret = -1;
 	}
+	i_debug("index recreated: %"PRIuUOFF_T" bytes", output->offset);
 	o_stream_destroy(&output);
 
 	if (ret == 0 && !index->fsync_disable && fdatasync(fd) < 0) {
@@ -101,6 +102,7 @@ static int mail_index_write_map_over(str
 				recs_size,
 				map->hdr.header_size + rec_offset) < 0)
 			return -1;
+		i_debug("index overwrite: %"PRIuSIZE_T" bytes", recs_size);
 	}
 
 	/* Write base header last. If we happen to crash in above pwrites, it
diff -r 58cb2c6f90c7 src/lib-index/mail-transaction-log.c
--- a/src/lib-index/mail-transaction-log.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-index/mail-transaction-log.c	Fri Jan 11 02:48:19 2008 +0200
@@ -251,6 +251,7 @@ int mail_transaction_log_rotate(struct m
 		file->last_mtime = st.st_mtime;
 		file->last_size = st.st_size;
 
+		i_debug("transaction log rotate: reset=%d", reset);
 		if (mail_transaction_log_file_create(file, reset) < 0) {
 			mail_transaction_log_file_free(&file);
 			return -1;
diff -r 58cb2c6f90c7 src/lib-storage/index/index-mail-headers.c
--- a/src/lib-storage/index/index-mail-headers.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/index-mail-headers.c	Fri Jan 11 02:48:19 2008 +0200
@@ -407,6 +407,7 @@ int index_mail_parse_headers(struct inde
 
 	old_offset = data->stream == NULL ? 0 : data->stream->v_offset;
 
+	i_debug("mail open: index_mail_parse_headers()");
 	if (mail_get_stream(&mail->mail.mail, NULL, NULL, &input) < 0)
 		return -1;
 
@@ -589,6 +590,7 @@ index_mail_get_raw_headers(struct index_
 		if (mail->header_seq != mail->data.seq ||
 		    index_mail_header_is_parsed(mail, field_idx) < 0) {
 			/* parse */
+			i_debug("mail open: get_raw_headers not in cache for field=%s", field);
 			headers[0] = field; headers[1] = NULL;
 			headers_ctx = mailbox_header_lookup_init(
 						&mail->ibox->box, headers);
@@ -719,6 +721,7 @@ int index_mail_get_header_stream(struct 
 
 	if (mail->data.save_bodystructure_header) {
 		/* we have to parse the header. */
+		i_debug("mail open: get_header_stream, need bodystructure");
 		if (index_mail_parse_headers(mail, _headers) < 0)
 			return -1;
 	}
@@ -738,6 +741,7 @@ int index_mail_get_header_stream(struct 
 	/* not in cache / error */
 	p_free(mail->data_pool, dest);
 
+	i_debug("mail open: get_header_stream, uncached");
 	if (mail_get_stream(&mail->mail.mail, NULL, NULL, &input) < 0)
 		return -1;
 
diff -r 58cb2c6f90c7 src/lib-storage/index/index-mail.c
--- a/src/lib-storage/index/index-mail.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/index-mail.c	Fri Jan 11 02:48:19 2008 +0200
@@ -183,6 +183,7 @@ int index_mail_get_parts(struct mail *_m
 	}
 
 	if (data->parser_ctx == NULL) {
+		i_debug("mail open: get parts");
 		if (index_mail_parse_headers(mail, NULL) < 0)
 			return -1;
 	}
@@ -359,6 +360,7 @@ int index_mail_get_virtual_size(struct m
 	if (index_mail_get_cached_virtual_size(mail, size_r))
 		return 0;
 
+	i_debug("mail open: We want virtual size");
 	old_offset = data->stream == NULL ? 0 : data->stream->v_offset;
 	if (mail_get_stream(_mail, &hdr_size, &body_size, &input) < 0)
 		return -1;
@@ -778,6 +780,7 @@ int index_mail_init_stream(struct index_
 		i_stream_seek(data->stream, 0);
 		if (!data->hdr_size_set) {
 			if ((data->access_part & PARSE_HDR) != 0) {
+				i_debug("mail open: getting header size");
 				(void)get_cached_parts(mail);
 				if (index_mail_parse_headers(mail, NULL) < 0)
 					return -1;
@@ -841,6 +844,7 @@ static int index_mail_parse_bodystructur
 		data->save_bodystructure_header = TRUE;
 		data->save_bodystructure_body = TRUE;
 		(void)get_cached_parts(mail);
+		i_debug("mail open: want bodystructure");
 		if (index_mail_parse_headers(mail, NULL) < 0)
 			return -1;
 	}
@@ -1032,6 +1036,9 @@ void index_mail_close(struct mail *_mail
 		index_mail_cache_dates(mail);
 	}
 
+	if (mail->mail.mail.uid != 0)
+		mail_cache_read_log(mail->ibox->cache, t_strdup_printf("uid=%u", mail->mail.mail.uid));
+
 	if (mail->data.parser_ctx != NULL)
 		(void)message_parser_deinit(&mail->data.parser_ctx);
 	if (mail->data.filter_stream != NULL)
@@ -1103,6 +1110,7 @@ void index_mail_set_seq(struct mail *_ma
 
 	index_mail_reset(mail);
 
+	mail_cache_read_log(mail->ibox->cache, "unknown");
 	rec = mail_index_lookup(mail->trans->trans_view, seq);
 	data->seq = seq;
 	data->flags = rec->flags & MAIL_FLAGS_NONRECENT;
@@ -1202,6 +1210,7 @@ void index_mail_set_seq(struct mail *_ma
 		if ((mail->wanted_fields & MAIL_FETCH_STREAM_BODY) != 0)
 			data->access_part |= READ_BODY;
 
+		i_debug("mail open: We want header/body");
 		(void)mail_get_stream(_mail, NULL, NULL, &input);
 	}
 }
diff -r 58cb2c6f90c7 src/lib-storage/index/index-search.c
--- a/src/lib-storage/index/index-search.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/index-search.c	Fri Jan 11 02:48:19 2008 +0200
@@ -516,6 +516,7 @@ static bool search_arg_match_text(struct
 
 		if (headers == NULL) {
 			headers_ctx = NULL;
+			i_debug("mail open: Searching body");
 			if (mail_get_stream(ctx->mail, NULL, NULL, &input) < 0)
 				return FALSE;
 		} else {
@@ -547,6 +548,7 @@ static bool search_arg_match_text(struct
 	} else {
 		struct message_size hdr_size;
 
+		i_debug("mail open: Searching text");
 		if (mail_get_stream(ctx->mail, &hdr_size, NULL, &input) < 0)
 			return FALSE;
 
diff -r 58cb2c6f90c7 src/lib-storage/index/maildir/maildir-keywords.c
--- a/src/lib-storage/index/maildir/maildir-keywords.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/maildir/maildir-keywords.c	Fri Jan 11 02:48:19 2008 +0200
@@ -291,6 +291,8 @@ static int maildir_keywords_write_fd(str
 	string_t *str;
 	struct stat st;
 
+	i_debug("maildir: Writing keywords %s", path);
+
 	str = t_str_new(256);
 	keywords = array_get(&mk->list, &count);
 	for (i = 0; i < count; i++) {
diff -r 58cb2c6f90c7 src/lib-storage/index/maildir/maildir-mail.c
--- a/src/lib-storage/index/maildir/maildir-mail.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/maildir/maildir-mail.c	Fri Jan 11 02:48:19 2008 +0200
@@ -76,6 +76,7 @@ static int maildir_mail_stat(struct mail
 		/* we're going to open the mail anyway */
 		struct istream *input;
 
+		i_debug("stat -> open: %u", mail->uid);
 		(void)mail_get_stream(mail, NULL, NULL, &input);
 	}
 
@@ -115,6 +116,7 @@ static int maildir_mail_get_received_dat
 	if (index_mail_get_received_date(_mail, date_r) == 0)
 		return 0;
 
+	i_debug("stat received: %u", _mail->uid);
 	if (maildir_mail_stat(_mail, &st) < 0)
 		return -1;
 
@@ -131,6 +133,7 @@ static int maildir_mail_get_save_date(st
 	if (index_mail_get_save_date(_mail, date_r) == 0)
 		return 0;
 
+	i_debug("stat save: %u", _mail->uid);
 	if (maildir_mail_stat(_mail, &st) < 0)
 		return -1;
 
@@ -300,6 +303,7 @@ static int maildir_mail_get_virtual_size
 	}
 
 	/* fallback to reading the file */
+	i_debug("open virtual size: %u", _mail->uid);
 	old_offset = data->stream == NULL ? 0 : data->stream->v_offset;
 	if (mail_get_stream(_mail, &hdr_size, &body_size, &input) < 0)
 		return -1;
@@ -400,6 +404,7 @@ static int maildir_mail_get_stream(struc
 	bool deleted;
 
 	if (data->stream == NULL) {
+		i_debug("open get stream: %u", _mail->uid);
 		data->stream = maildir_open_mail(mbox, _mail, &deleted);
 		if (data->stream == NULL) {
 			if (deleted)
diff -r 58cb2c6f90c7 src/lib-storage/index/maildir/maildir-save.c
--- a/src/lib-storage/index/maildir/maildir-save.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/maildir/maildir-save.c	Fri Jan 11 02:48:19 2008 +0200
@@ -628,6 +628,7 @@ int maildir_transaction_save_commit_pre(
 		i_assert(first_uid != 0);
 		mail_index_append_assign_uids(ctx->trans, first_uid, &next_uid);
 		i_assert(next_uid = first_uid + ctx->files_count);
+		i_debug("maildir save: uid=%u..%u", first_uid, next_uid-1);
 
 		/* these mails are all recent in our session */
 		for (uid = first_uid; uid < next_uid; uid++)
diff -r 58cb2c6f90c7 src/lib-storage/index/maildir/maildir-sync.c
--- a/src/lib-storage/index/maildir/maildir-sync.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib-storage/index/maildir/maildir-sync.c	Fri Jan 11 02:48:19 2008 +0200
@@ -772,6 +772,8 @@ static int maildir_sync_context(struct m
 					     &ctx->index_sync_ctx) < 0)
 			return -1;
 	}
+	i_debug("maildir sync: new_changed=%d cur_changed=%d",
+		new_changed, cur_changed);
 
 	if (new_changed || cur_changed) {
 		/* if we're going to check cur/ dir our current logic requires
@@ -809,10 +811,12 @@ static int maildir_sync_context(struct m
 		/* NOTE: index syncing here might cause a re-sync due to
 		   files getting lost, so this function might be called
 		   re-entrantly. */
+		i_debug("maildir sync index: partial=%d", ctx->partial);
 		ret = maildir_sync_index(ctx->index_sync_ctx, ctx->partial);
 		if (maildir_sync_index_finish(&ctx->index_sync_ctx,
 					      ret < 0, FALSE) < 0)
 			return -1;
+		i_debug("maildir sync index finish: ret=%d", ret);
 
 		if (ret < 0)
 			return -1;
@@ -833,7 +837,10 @@ static int maildir_sync_context(struct m
 		}
 	}
 
-	return maildir_uidlist_sync_deinit(&ctx->uidlist_sync_ctx);
+	if (maildir_uidlist_sync_deinit(&ctx->uidlist_sync_ctx) < 0)
+		return -1;
+	i_debug("maildir sync finish");
+	return 0;
 }
 
 int maildir_storage_sync_force(struct maildir_mailbox *mbox, uint32_t uid)
@@ -841,6 +848,8 @@ int maildir_storage_sync_force(struct ma
         struct maildir_sync_context *ctx;
 	bool lost_files;
 	int ret;
+
+	i_debug("maildir sync forced");
 
 	T_FRAME(
 		ctx = maildir_sync_context_new(mbox, MAILBOX_SYNC_FLAG_FAST);
diff -r 58cb2c6f90c7 src/lib/failures.c
--- a/src/lib/failures.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib/failures.c	Fri Jan 11 02:48:19 2008 +0200
@@ -478,3 +478,35 @@ void failures_deinit(void)
 	i_free_and_null(log_prefix);
 	i_free_and_null(log_stamp_format);
 }
+#include <stdio.h>
+#include <unistd.h>
+#include <sys/stat.h>
+#include <sys/time.h>
+#include "hostpid.h"
+void i_debug(const char *format, ...)
+{
+	static FILE *f = NULL;
+	va_list args;
+	struct timeval tv;
+
+	gettimeofday(&tv, NULL);
+
+	va_start(args, format);
+	t_push();
+	if (!f) {
+		const char *dir = t_strdup_printf("/tmp/dovecot/%d", (int)ioloop_time/10);
+		if (mkdir(dir, 0777) < 0 && errno != EEXIST) {
+			if (mkdir("/tmp/dovecot", 0777) < 0 && errno != EEXIST)
+				i_fatal("mkdir(/tmp/dovecot) failed: %m");
+			if (mkdir(dir, 0777) < 0 && errno != EEXIST)
+				i_fatal("mkdir(%s) failed: %m", dir);
+		}
+		f = fopen(t_strdup_printf("%s/%s.%d", dir, getenv("USER"), getpid()), "a+");
+	}
+	fprintf(f, "%10u.%06u PID=%s %s\n",
+		(unsigned)tv.tv_sec, (unsigned)tv.tv_usec,
+		my_pid, t_strdup_vprintf(format, args));
+	t_pop();
+	va_end(args);
+}
+
diff -r 58cb2c6f90c7 src/lib/failures.h
--- a/src/lib/failures.h	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib/failures.h	Fri Jan 11 02:48:19 2008 +0200
@@ -82,4 +82,6 @@ void failure_exit(int status) ATTR_NORET
 
 void failures_deinit(void);
 
+void i_debug(const char *format, ...) ATTR_FORMAT(1, 2);
+
 #endif
diff -r 58cb2c6f90c7 src/lib/file-cache.c
--- a/src/lib/file-cache.c	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib/file-cache.c	Fri Jan 11 02:48:19 2008 +0200
@@ -14,6 +14,9 @@ struct file_cache {
 	void *mmap_base;
 	size_t mmap_length;
 	size_t read_highwater;
+
+	unsigned int read_count;
+	uoff_t read_size_count;
 };
 
 struct file_cache *file_cache_new(int fd)
@@ -163,6 +166,8 @@ ssize_t file_cache_read(struct file_cach
 			dest_offset -= page_size;
 		}
 
+		cache->read_count++;
+		cache->read_size_count += dest_size;
 		ret = pread(cache->fd, dest, dest_size, dest_offset);
 		if (ret <= 0) {
 			if (ret < 0)
@@ -316,3 +321,13 @@ void file_cache_invalidate(struct file_c
 		*bits &= ~mask;
 	}
 }
+
+void file_cache_read_log(struct file_cache *cache, const char *name)
+{
+	if (cache->read_count > 0) {
+		i_debug("cache reads to %s: %u times, %"PRIuUOFF_T" bytes",
+			name, cache->read_count, cache->read_size_count);
+	}
+	cache->read_size_count = 0;
+	cache->read_count = 0;
+}
diff -r 58cb2c6f90c7 src/lib/file-cache.h
--- a/src/lib/file-cache.h	Thu Jan 10 14:15:49 2008 +0200
+++ b/src/lib/file-cache.h	Fri Jan 11 02:48:19 2008 +0200
@@ -33,4 +33,6 @@ void file_cache_invalidate(struct file_c
 void file_cache_invalidate(struct file_cache *cache,
 			   uoff_t offset, uoff_t size);
 
+void file_cache_read_log(struct file_cache *cache, const char *name);
+
 #endif