[VM] Weird performance issue with a VM folder

[Daniel Barrett]

I have a VM mail folder with a mysterious performance problem. When
visited with vm-visit-folder, it loads very slowly. For 400 messages
(28MB), it takes about 6 seconds to load. All my other mail folders,
even much larger ones, load instantly (maybe 0.1 seconds).

I was able to fix it by removing all of the "X-VM-..." headers in the
file and letting VM load and save the folder, writing new headers. But
I am curious about *which* headers caused this performance
problem. I'd like to track it down to report a bug.

The old headers at the top of the file were:

X-VM-v5-Data: ([nil nil nil nil nil nil nil nil t nil nil nil nil nil nil nil]
["17232" "Friday" "15" "February" "2013" "11:38:17" "-0800" "Name Lastname" "***@XXXXXX.YYY.ZZ.US" nil "317" "8th Grade student/parent night XXHS" "^From:" nil nil "2" nil "8th Grade student/parent night XXHS" (number " " mark " B Name Lastname Feb 15 317/17232 " thread-indent "\"8th Grade student/parent night XXHS\"\n") nil nil nil nil nil nil nil]
nil)
X-VM-Summary-Format: "%n %*%a %-17.17F %-3.3m %2d %4l/%-5c %I\"%s\"\n"
X-VM-Labels: nil
X-VM-VHeader: ("Resent-" "From:" "Sender:" "To:" "Newsgroups:" "Apparently-To:" "Cc:" "Subject:" "Date:") nil
X-VM-Last-Modified: (21629 51968 231600 190000)
X-VM-IMAP-Retrieved: nil
X-VM-POP-Retrieved: nil
X-VM-Bookmark: 430

The new, good headers became:

X-VM-v5-Data: ([nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil]
["17232" "Friday" "15" "February" "2013" "11:38:17" "-0800" "Name Lastname" "***@XXXXXX.YYY.ZZ.US" nil "317" "8th Grade student/parent night XXHS" "^From:" nil nil "2" nil nil (number " " mark " Name Lastname Feb 15 317/17232 " thread-indent "\"8th Grade student/parent night XXHS\"\n") nil nil nil nil nil nil nil]
nil)
X-VM-Summary-Format: "%n %*%a %-17.17F %-3.3m %2d %4l/%-5c %I\"%s\"\n"
X-VM-Labels: nil
X-VM-VHeader: ("Resent-" "From:" "Sender:" "To:" "Newsgroups:" "Apparently-To:" "Cc:" "Subject:" "Date:") nil
X-VM-Last-Modified: (21639 20941 92687 525000)
X-VM-IMAP-Retrieved: nil
X-VM-POP-Retrieved: nil
X-VM-Bookmark: 235

Any clues?
Thanks.

--
Dan Barrett
***@blazemonger.com

[Uday Reddy]

Post by Daniel Barrett
X-VM-v5-Data: ([nil nil nil nil nil nil nil nil t nil nil nil nil nil nil nil]
nil)
X-VM-Summary-Format: "%n %*%a %-17.17F %-3.3m %2d %4l/%-5c %I\"%s\"\n"
X-VM-Labels: nil
X-VM-VHeader: ("Resent-" "From:" "Sender:" "To:" "Newsgroups:" "Apparently-To:" "Cc:" "Subject:" "Date:") nil
X-VM-Last-Modified: (21629 51968 231600 190000)
X-VM-IMAP-Retrieved: nil
X-VM-POP-Retrieved: nil
X-VM-Bookmark: 430

I don't see anything suspicious in these headers. If you still have the old
version of the folder, please try profiling. Here are some quick notes on
how to do profiling. (More details in the elp.el library file - part of
Emacs distribution.)

* Profiling - elp
- M-x elp-instrument-package RET vm RET should instrument the whole
package. (M-x elp-instrument-function and M-x elp-instrument-list or
other ways to set profiling.)
- M-x elp-set-master sets a "master" function, whose execution is profiled
and nothing else. M-x elp-unset-master cancels the master function.
- M-x elp-results shows the results.
- M-x elp-reset-all to reset the profiling data
- M-x elp-restore-all to remove all profiling.

Cheers,
Uday

[Daniel Barrett]

If you still have the old version of the folder, please try profiling.

Thanks for the suggestion - I didn't even know emacs did profiling.
I've included profiles of running vm-visit-folder on "good" and "bad"
folders of about 450 messages for comparison. I've included the lines
that most clearly differentiate the two runs.

The "good" folder was processed in 0.6 seconds:

vm-visit-folder 1 0.66686915 0.66686915
vm 1 0.578879675 0.578879675
vm-decode-mime-encoded-words 189 0.361880942 0.0019147139
vm-update-summary-and-mode-line 4 0.3322451050 0.0830612762
vm-summarize 1 0.331768543 0.331768543
vm-do-needed-summary-rebuild 2 0.331305685 0.1656528425
vm-do-summary 1 0.331071934 0.331071934
vm-decode-mime-encoded-words-in-string 1387 0.311080336 0.0002242828
vm-mime-base64-decode-region 189 0.2735256769 0.0014472258
vm-run-command-on-region 8 0.260684395 0.0325855493
vm-su-summary 453 0.206757816 0.0004564190
vm-summary-sprintf 4 0.206496776 0.051624194
vm-tokenized-summary-insert 453 0.1132789349 0.0002500638
...
vm-find-leading-message-separator 907 0.0361465239 3.985...e-05
vm-insert-char 4506 0.0336452009 7.466...e-06
...
vm-xemacs-compatible-insert-char 4506 0.0035975850 7.983...e-07
...
vm-left-justify-string 12 0.000122272 1.018...e-05
...
vm-right-justify-string 8 6.810...e-05 8.513...e-06

The "bad" folder contained 99% of the same messages and took almost 6 seconds:

vm-visit-folder 1 5.902866221 5.902866221
vm 1 5.82534551 5.82534551
vm-summarize 1 5.652573062 5.652573062
vm-update-summary-and-mode-line 3 5.6430740480 1.8810246826
vm-do-needed-summary-rebuild 1 5.642558428 5.642558428
vm-do-summary 1 5.642472744 5.642472744
vm-su-summary 449 5.5901255799 0.0124501683
vm-summary-sprintf 430 5.5849337159 0.0129882179
vm-decode-mime-encoded-words-in-string 4358 5.4500003469 0.0012505737
vm-decode-mime-encoded-words 182 5.4220282910 0.0297913642
vm-mime-base64-decode-region 183 5.3929850379 0.0294698635
vm-run-command-on-region 182 5.3591683290 0.0294459798
vm-read-folder 1 0.092051119 0.092051119
...
vm-find-trailing-message-separator 449 0.035558065 7.919...e-05
vm-find-leading-message-separator 899 0.0354277910 3.940...e-05
vm-tokenized-summary-insert 449 0.0256965510 5.723...e-05
vm-left-justify-string 1290 0.0252046220 1.953...e-05
...
vm-right-justify-string 860 0.0067221149 7.816...e-06
...
vm-string-width 2150 0.0050137250 2.331...e-06
vm-truncate-string 860 0.0038709260 4.501...e-06
...
vm-insert-char 17 5.052...e-05 2.971...e-06
...
vm-xemacs-compatible-insert-char 17 1.3549e-05 7.970...e-07

Hope this helps!! Let me know if you want me to file a bug containing the full
output.

--
Dan Barrett
***@blazemonger.com