unofficial mirror of bug-gnu-emacs@gnu.org 
 help / color / mirror / code / Atom feed
* bug#28227: 26.0.50; Tramp tests are slow
@ 2017-08-24 21:03 Gemini Lasswell
  2017-08-25  8:04 ` Michael Albinus
  0 siblings, 1 reply; 9+ messages in thread
From: Gemini Lasswell @ 2017-08-24 21:03 UTC (permalink / raw)
  To: 28227

[-- Attachment #1: Type: text/plain, Size: 528 bytes --]

The Tramp tests are the slowest tests in Emacs's test suite, even when
they aren't set up to access a remote machine.

After a little investigation I think the cause of the slowness is
excessive memory allocation. I modified ert-run-tests to print
memory statistics after each test and found that tramp-tests.el, which
takes 100 seconds to run on my machine, is spending 39 seconds doing
garbage collection, and by the end of the test run has allocated and
freed 27 million strings.

Here is a log file with memory statistics:


[-- Attachment #2: tramp-tests.log --]
[-- Type: text/plain, Size: 24307 bytes --]

Running 53 tests (2017-08-24 12:39:32-0700)
Remote directory: `/mock::/run/user/1000/'
   passed   1/53  tramp-test00-availability
GC: ((conses 16 333692 35342) (symbols 48 25154 2) (miscs 40 27 66) (strings 32 37316 2023) (string-bytes 1 1025538) (vectors 16 34701) (vector-slots 8 697440 7506) (floats 8 69 47) (intervals 56 26 39) (buffers 992 7))
GC count: 24 time: 0.29961145299999997
Memory-use-counts: (1349843 837 1571731 25200 5571631 580 321 152749)
   passed   2/53  tramp-test01-file-name-syntax
GC: ((conses 16 334015 35019) (symbols 48 25154 2) (miscs 40 27 66) (strings 32 37316 2023) (string-bytes 1 1025810) (vectors 16 34702) (vector-slots 8 697444 7502) (floats 8 69 47) (intervals 56 26 39) (buffers 992 7))
GC count: 25 time: 0.31423798399999997
Memory-use-counts: (1350961 838 1572272 25200 5590666 592 321 153150)
   passed   3/53  tramp-test01-file-name-syntax-separate
GC: ((conses 16 333977 34809) (symbols 48 25154 2) (miscs 40 25 68) (strings 32 37242 733) (string-bytes 1 1026111) (vectors 16 34597) (vector-slots 8 689783 15163) (floats 8 69 47) (intervals 56 25 40) (buffers 992 6))
GC count: 26 time: 0.33028826099999997
Memory-use-counts: (1352148 839 1574261 25200 5614929 606 321 153524)
   passed   4/53  tramp-test01-file-name-syntax-simplified
GC: ((conses 16 334177 34609) (symbols 48 25154 2) (miscs 40 25 68) (strings 32 37242 702) (string-bytes 1 1026609) (vectors 16 34598) (vector-slots 8 689787 15159) (floats 8 69 47) (intervals 56 25 40) (buffers 992 6))
GC count: 27 time: 0.345071882
Memory-use-counts: (1353135 840 1576194 25200 5633238 618 321 153884)
   passed   5/53  tramp-test02-file-name-dissect
GC: ((conses 16 335838 32948) (symbols 48 25154 2) (miscs 40 25 68) (strings 32 37441 4409) (string-bytes 1 1028070) (vectors 16 34714) (vector-slots 8 698140 6806) (floats 8 69 47) (intervals 56 127 266) (buffers 992 6))
GC count: 35 time: 0.47771925299999995
Memory-use-counts: (1426457 848 1609540 25200 10138322 630 1828 256493)
   passed   6/53  tramp-test02-file-name-dissect-separate
GC: ((conses 16 337722 31064) (symbols 48 25154 2) (miscs 40 25 68) (strings 32 37559 5872) (string-bytes 1 1031150) (vectors 16 34600) (vector-slots 8 689795 15151) (floats 8 69 47) (intervals 56 251 378) (buffers 992 6))
GC count: 45 time: 0.6440376459999999
Memory-use-counts: (1534450 858 1655587 25200 16534204 642 4448 359080)
   passed   7/53  tramp-test02-file-name-dissect-simplified
GC: ((conses 16 338583 30203) (symbols 48 25154 2) (miscs 40 25 68) (strings 32 37640 6752) (string-bytes 1 1032143) (vectors 16 34601) (vector-slots 8 689799 15147) (floats 8 69 47) (intervals 56 289 370) (buffers 992 6))
GC count: 50 time: 0.7264122249999998
Memory-use-counts: (1580066 863 1676845 25200 18966799 654 5772 410998)
   passed   8/53  tramp-test03-file-name-defaults
GC: ((conses 16 345517 24191) (symbols 48 26067 0) (miscs 40 27 49) (strings 32 42104 4489) (string-bytes 1 1205469) (vectors 16 36552) (vector-slots 8 722223 9812) (floats 8 98 185) (intervals 56 316 347) (buffers 992 6))
GC count: 53 time: 0.7798698979999998
Memory-use-counts: (1703384 2525 1728765 26114 19755290 1600 7806 435331)
   passed   9/53  tramp-test04-substitute-in-file-name
GC: ((conses 16 345677 24031) (symbols 48 26067 0) (miscs 40 27 49) (strings 32 42114 4603) (string-bytes 1 1205612) (vectors 16 36558) (vector-slots 8 722590 9445) (floats 8 98 185) (intervals 56 316 347) (buffers 992 6))
GC count: 55 time: 0.8133753799999999
Memory-use-counts: (1718258 2527 1734852 26114 20734119 1612 7806 457317)
   passed  10/53  tramp-test05-expand-file-name
GC: ((conses 16 345730 23978) (symbols 48 26067 0) (miscs 40 27 49) (strings 32 42119 4505) (string-bytes 1 1205725) (vectors 16 36559) (vector-slots 8 722594 9441) (floats 8 98 185) (intervals 56 316 347) (buffers 992 6))
GC count: 56 time: 0.8295698519999999
Memory-use-counts: (1720771 2528 1736076 26114 20868600 1624 7806 460355)
   failed  11/53  tramp-test05-expand-file-name-relative
GC: ((conses 16 346093 23553) (symbols 48 26067 0) (miscs 40 29 67) (strings 32 42181 5683) (string-bytes 1 1206315) (vectors 16 36657) (vector-slots 8 729547 5554) (floats 8 98 185) (intervals 56 317 346) (buffers 992 7))
GC count: 58 time: 0.8670432959999999
Memory-use-counts: (1746541 2554 1751400 26114 22061019 1703 7808 486642)
   passed  12/53  tramp-test06-directory-file-name
GC: ((conses 16 346099 23547) (symbols 48 26067 0) (miscs 40 29 67) (strings 32 42145 4913) (string-bytes 1 1206094) (vectors 16 36583) (vector-slots 8 724106 8951) (floats 8 98 185) (intervals 56 316 347) (buffers 992 7))
GC count: 60 time: 0.9034700749999999
Memory-use-counts: (1758238 2556 1757408 26114 22830399 1717 7808 503773)
   passed  13/53  tramp-test07-file-exists-p
GC: ((conses 16 346431 23215) (symbols 48 26067 0) (miscs 40 31 53) (strings 32 42222 6200) (string-bytes 1 1206744) (vectors 16 36680) (vector-slots 8 731049 5585) (floats 8 98 185) (intervals 56 317 346) (buffers 992 8))
GC count: 66 time: 1.02241443
Memory-use-counts: (1831498 2673 1792494 26114 26249154 2006 7838 580816)
   passed  14/53  tramp-test08-file-local-copy
GC: ((conses 16 346478 23168) (symbols 48 26067 2) (miscs 40 33 60) (strings 32 42226 6320) (string-bytes 1 1206829) (vectors 16 36677) (vector-slots 8 730732 8457) (floats 8 98 185) (intervals 56 321 342) (buffers 992 9))
GC count: 77 time: 1.234111201
Memory-use-counts: (1959677 2902 1849901 26118 33035357 2428 7924 732993)
   passed  15/53  tramp-test09-insert-file-contents
GC: ((conses 16 346577 23069) (symbols 48 26067 2) (miscs 40 36 53) (strings 32 42241 6429) (string-bytes 1 1206971) (vectors 16 36684) (vector-slots 8 731141 8559) (floats 8 98 185) (intervals 56 321 345) (buffers 992 11))
GC count: 96 time: 1.6589619950000005
Memory-use-counts: (2180020 3235 1946060 26118 44891427 3117 8980 999504)
   passed  16/53  tramp-test10-write-region
GC: ((conses 16 346813 22833) (symbols 48 26069 0) (miscs 40 38 42) (strings 32 42265 6839) (string-bytes 1 1207426) (vectors 16 36692) (vector-slots 8 731560 7629) (floats 8 98 185) (intervals 56 321 330) (buffers 992 12))
GC count: 147 time: 2.474707581
Memory-use-counts: (2755485 4163 2187558 26120 77348481 5076 11586 1716316)
   passed  17/53  tramp-test11-copy-file
GC: ((conses 16 346932 22714) (symbols 48 26069 0) (miscs 40 40 71) (strings 32 42278 6919) (string-bytes 1 1207810) (vectors 16 36699) (vector-slots 8 731969 7220) (floats 8 98 185) (intervals 56 321 344) (buffers 992 13))
GC count: 177 time: 2.9057925529999995
Memory-use-counts: (3086469 4641 2329962 26120 96657839 5652 13418 2140066)
   passed  18/53  tramp-test12-rename-file
GC: ((conses 16 347123 22523) (symbols 48 26069 0) (miscs 40 42 71) (strings 32 42293 7121) (string-bytes 1 1208191) (vectors 16 36706) (vector-slots 8 732378 7833) (floats 8 98 185) (intervals 56 321 340) (buffers 992 14))
GC count: 216 time: 3.7685096670000005
Memory-use-counts: (3526262 5349 2524104 26120 121554062 6533 15502 2689107)
   passed  19/53  tramp-test13-make-directory
GC: ((conses 16 347222 22424) (symbols 48 26069 0) (miscs 40 44 69) (strings 32 42296 6994) (string-bytes 1 1208393) (vectors 16 36713) (vector-slots 8 732787 7424) (floats 8 98 185) (intervals 56 321 331) (buffers 992 15))
GC count: 222 time: 3.9243306980000003
Memory-use-counts: (3593892 5441 2558414 26120 125346081 6670 16644 2767796)
   passed  20/53  tramp-test14-delete-directory
GC: ((conses 16 347350 22296) (symbols 48 26069 0) (miscs 40 46 75) (strings 32 42310 7321) (string-bytes 1 1208684) (vectors 16 36725) (vector-slots 8 733559 8696) (floats 8 98 185) (intervals 56 321 338) (buffers 992 16))
GC count: 230 time: 4.113979932
Memory-use-counts: (3691116 5575 2607752 26120 130445976 7003 17802 2876184)
   passed  21/53  tramp-test15-copy-directory
GC: ((conses 16 347601 22045) (symbols 48 26069 0) (miscs 40 48 59) (strings 32 42324 7400) (string-bytes 1 1209375) (vectors 16 36727) (vector-slots 8 733605 7117) (floats 8 98 185) (intervals 56 321 338) (buffers 992 17))
GC count: 279 time: 5.069164020000002
Memory-use-counts: (4221494 6117 2871728 26120 161332248 7928 17860 3568223)
   passed  22/53  tramp-test16-directory-files
GC: ((conses 16 347796 21850) (symbols 48 26069 0) (miscs 40 50 68) (strings 32 42362 7548) (string-bytes 1 1210540) (vectors 16 36734) (vector-slots 8 734014 7730) (floats 8 98 185) (intervals 56 321 338) (buffers 992 18))
GC count: 290 time: 5.276773825000003
Memory-use-counts: (4354171 6289 2934332 26120 168117781 8411 17906 3720789)
   passed  23/53  tramp-test17-dired-with-wildcards
GC: ((conses 16 348084 21562) (symbols 48 26069 0) (miscs 40 58 49) (strings 32 42405 8063) (string-bytes 1 1211796) (vectors 16 36751) (vector-slots 8 735149 7106) (floats 8 98 185) (intervals 56 321 338) (buffers 992 25))
GC count: 327 time: 5.909913256
Memory-use-counts: (4777828 6666 3117779 26120 191638493 11240 18682 4248788)
   passed  24/53  tramp-test17-insert-directory
GC: ((conses 16 348162 21484) (symbols 48 26069 0) (miscs 40 60 60) (strings 32 42413 8024) (string-bytes 1 1212323) (vectors 16 36748) (vector-slots 8 734832 8445) (floats 8 98 185) (intervals 56 321 338) (buffers 992 26))
GC count: 339 time: 6.1275310140000006
Memory-use-counts: (4913498 6834 3179978 26120 198855051 11765 18732 4410971)
checkpoint 1
checkpoint 2
checkpoint 3
checkpoint 4
checkpoint 5
checkpoint 1
checkpoint 2
checkpoint 3
checkpoint 4
checkpoint 5
   passed  25/53  tramp-test18-file-attributes
GC: ((conses 16 348696 20950) (symbols 48 26069 0) (miscs 40 64 54) (strings 32 42442 8150) (string-bytes 1 1213146) (vectors 16 36755) (vector-slots 8 735241 9058) (floats 8 98 185) (intervals 56 321 338) (buffers 992 27))
GC count: 357 time: 6.498652796
Memory-use-counts: (5119395 7165 3276543 26120 209898105 12288 18774 4659078)
   passed  26/53  tramp-test19-directory-files-and-attributes
GC: ((conses 16 349594 20052) (symbols 48 26069 0) (miscs 40 66 66) (strings 32 42480 8546) (string-bytes 1 1213631) (vectors 16 36762) (vector-slots 8 735650 9160) (floats 8 98 185) (intervals 56 321 338) (buffers 992 28))
GC count: 376 time: 6.858420304
Memory-use-counts: (5338413 7604 3378715 26120 221788533 12949 18836 4925033)
   passed  27/53  tramp-test20-file-modes
GC: ((conses 16 349741 19905) (symbols 48 26069 0) (miscs 40 68 77) (strings 32 42485 8417) (string-bytes 1 1213706) (vectors 16 36769) (vector-slots 8 736059 8240) (floats 8 98 185) (intervals 56 321 338) (buffers 992 29))
GC count: 387 time: 7.069165169000001
Memory-use-counts: (5466267 7854 3438782 26120 228297784 13298 18866 5071348)
   passed  28/53  tramp-test21-file-links
GC: ((conses 16 350074 19572) (symbols 48 26069 0) (miscs 40 70 58) (strings 32 42522 8597) (string-bytes 1 1215166) (vectors 16 36781) (vector-slots 8 736831 9512) (floats 8 98 185) (intervals 56 321 330) (buffers 992 30))
GC count: 415 time: 7.699926090000001
Memory-use-counts: (5785387 8388 3586360 26120 246515972 14217 22328 5455307)
   passed  29/53  tramp-test22-file-times
GC: ((conses 16 350243 19403) (symbols 48 26069 1) (miscs 40 72 77) (strings 32 42533 8896) (string-bytes 1 1215222) (vectors 16 36793) (vector-slots 8 737603 7718) (floats 8 98 185) (intervals 56 321 330) (buffers 992 31))
GC count: 430 time: 8.054803152
Memory-use-counts: (5958713 8699 3665593 26121 255530780 14757 22618 5658090)
   passed  30/53  tramp-test23-visited-file-modtime
GC: ((conses 16 350314 19332) (symbols 48 26069 1) (miscs 40 74 53) (strings 32 42531 8929) (string-bytes 1 1215261) (vectors 16 36790) (vector-slots 8 737286 9568) (floats 8 98 185) (intervals 56 321 330) (buffers 992 32))
GC count: 440 time: 8.231517479999999
Memory-use-counts: (6076738 8916 3718080 26121 261572275 15156 22676 5793980)
   passed  31/53  tramp-test24-file-name-completion
GC: ((conses 16 350940 18706) (symbols 48 26069 1) (miscs 40 36 107) (strings 32 42519 8786) (string-bytes 1 1215512) (vectors 16 36592) (vector-slots 8 723424 21386) (floats 8 98 185) (intervals 56 308 343) (buffers 992 13))
GC count: 481 time: 8.900587976999999
Memory-use-counts: (6547895 9336 3969300 26121 286293947 16389 22810 6377531)
   passed  32/53  tramp-test25-load
GC: ((conses 16 351531 18115) (symbols 48 26099 3) (miscs 40 38 100) (strings 32 42663 9293) (string-bytes 1 1218630) (vectors 16 36728) (vector-slots 8 729336 12408) (floats 8 98 185) (intervals 56 308 343) (buffers 992 14))
GC count: 498 time: 9.245687284999997
Memory-use-counts: (6761049 9686 4065490 26154 296481267 17528 22868 6606860)
   passed  33/53  tramp-test26-process-file
GC: ((conses 16 351416 18230) (symbols 48 26099 3) (miscs 40 42 103) (strings 32 42606 8730) (string-bytes 1 1217672) (vectors 16 36665) (vector-slots 8 724663 16570) (floats 8 98 185) (intervals 56 308 343) (buffers 992 17))
GC count: 505 time: 9.394883368999997
Memory-use-counts: (6840926 9811 4102646 26155 300215035 17871 22898 6691046)
   passed  34/53  tramp-test27-start-file-process
GC: ((conses 16 351752 17894) (symbols 48 26099 3) (miscs 40 56 96) (strings 32 42650 8810) (string-bytes 1 1217931) (vectors 16 36708) (vector-slots 8 727502 13731) (floats 8 98 185) (intervals 56 309 342) (buffers 992 24))
GC count: 512 time: 9.579070246999997
Memory-use-counts: (6938152 9962 4145298 26155 304063173 18555 22930 6778726)
   passed  35/53  tramp-test28-shell-command
GC: ((conses 16 352066 17580) (symbols 48 26099 3) (miscs 40 66 132) (strings 32 42689 9236) (string-bytes 1 1218732) (vectors 16 36739) (vector-slots 8 729531 11702) (floats 8 99 184) (intervals 56 313 338) (buffers 992 29))
GC count: 530 time: 10.008044569999997
Memory-use-counts: (7159225 10282 4244730 26155 315144483 19656 23000 7028575)
   passed  36/53  tramp-test29-environment-variables
GC: ((conses 16 352363 17283) (symbols 48 26099 3) (miscs 40 84 144) (strings 32 42735 9965) (string-bytes 1 1371122) (vectors 16 36794) (vector-slots 8 733180 8053) (floats 8 99 184) (intervals 56 313 338) (buffers 992 38))
GC count: 541 time: 10.307847671999998
Memory-use-counts: (7294215 10411 4315546 26155 321797754 20647 23044 7164516)
   passed  37/53  tramp-test29-environment-variables-and-port-numbers
GC: ((conses 16 352219 17427) (symbols 48 26099 3) (miscs 40 88 140) (strings 32 42702 9502) (string-bytes 1 1369851) (vectors 16 36737) (vector-slots 8 728912 13343) (floats 8 99 184) (intervals 56 312 339) (buffers 992 40))
GC count: 545 time: 10.425527692999998
Memory-use-counts: (7341185 10463 4347776 26156 323895561 20793 23048 7211903)
   passed  38/53  tramp-test30-explicit-shell-file-name
GC: ((conses 16 352607 17112) (symbols 48 26099 3) (miscs 40 92 136) (strings 32 42782 10414) (string-bytes 1 1370583) (vectors 16 36835) (vector-slots 8 735897 6358) (floats 8 99 184) (intervals 56 313 338) (buffers 992 42))
GC count: 549 time: 10.525123750999995
Memory-use-counts: (7386471 10532 4370289 26159 325981042 20967 23050 7258776)
  skipped  39/53  tramp-test31-vc-registered
GC: ((conses 16 352695 17024) (symbols 48 26099 3) (miscs 40 94 134) (strings 32 42771 9960) (string-bytes 1 1370525) (vectors 16 36838) (vector-slots 8 735953 9368) (floats 8 99 184) (intervals 56 313 338) (buffers 992 43))
GC count: 553 time: 10.606368909999997
Memory-use-counts: (7425061 10582 4390194 26160 327941646 21045 23058 7302611)
   passed  40/53  tramp-test32-make-auto-save-file-name
GC: ((conses 16 352752 16967) (symbols 48 26101 1) (miscs 40 96 132) (strings 32 42786 10286) (string-bytes 1 1370872) (vectors 16 36845) (vector-slots 8 736362 6404) (floats 8 99 184) (intervals 56 313 338) (buffers 992 44))
GC count: 558 time: 10.690769160999997
Memory-use-counts: (7474095 10617 4417774 26162 330613105 21152 23084 7362320)
   passed  41/53  tramp-test33-make-nearby-temp-file
GC: ((conses 16 352951 16768) (symbols 48 26101 1) (miscs 40 98 130) (strings 32 42818 9975) (string-bytes 1 1371301) (vectors 16 36862) (vector-slots 8 737497 9357) (floats 8 99 184) (intervals 56 324 364) (buffers 992 45))
GC count: 565 time: 10.814019615999998
Memory-use-counts: (7562997 10743 4455243 26163 334708960 21327 25269 7454635)
   passed  42/53  tramp-test34-special-characters
GC: ((conses 16 356078 13641) (symbols 48 26101 1) (miscs 40 100 128) (strings 32 43219 12240) (string-bytes 1 1388676) (vectors 16 36859) (vector-slots 8 737347 8996) (floats 8 99 184) (intervals 56 352 300) (buffers 992 46))
GC count: 783 time: 15.322561587000001
Memory-use-counts: (10026155 14902 5530550 26163 478367735 26208 26495 10639167)
   passed  43/53  tramp-test34-special-characters-with-ls
GC: ((conses 16 359353 11071) (symbols 48 26107 0) (miscs 40 102 126) (strings 32 43639 13060) (string-bytes 1 1406085) (vectors 16 36876) (vector-slots 8 738482 7861) (floats 8 99 184) (intervals 56 383 269) (buffers 992 47))
GC count: 1110 time: 21.752231962999964
Memory-use-counts: (13648383 18242 7074808 26169 696510344 32878 27721 15490900)
   passed  44/53  tramp-test34-special-characters-with-perl
GC: ((conses 16 362533 10865) (symbols 48 26107 0) (miscs 40 104 124) (strings 32 44043 13896) (string-bytes 1 1423327) (vectors 16 36873) (vector-slots 8 738165 10733) (floats 8 99 184) (intervals 56 414 238) (buffers 992 48))
GC count: 1326 time: 26.874272779999973
Memory-use-counts: (16125349 20779 8149789 26169 840322586 37436 28947 18678185)
   passed  45/53  tramp-test34-special-characters-with-stat
GC: ((conses 16 365763 11345) (symbols 48 26107 0) (miscs 40 106 122) (strings 32 44459 13945) (string-bytes 1 1440774) (vectors 16 36880) (vector-slots 8 738574 9813) (floats 8 99 184) (intervals 56 445 207) (buffers 992 49))
GC count: 1541 time: 31.182403089999994
Memory-use-counts: (18641949 24928 9226828 26169 984193733 41954 30173 21868299)
   passed  46/53  tramp-test35-utf8
GC: ((conses 16 366676 11556) (symbols 48 26107 0) (miscs 40 108 120) (strings 32 44576 14107) (string-bytes 1 1453230) (vectors 16 36887) (vector-slots 8 738983 9915) (floats 8 99 184) (intervals 56 443 209) (buffers 992 50))
GC count: 1606 time: 32.528721307999994
Memory-use-counts: (19374605 26117 9534698 26169 1026182727 43267 30173 22871751)
   passed  47/53  tramp-test35-utf8-with-ls
GC: ((conses 16 367646 11058) (symbols 48 26107 0) (miscs 40 110 118) (strings 32 44691 14240) (string-bytes 1 1465540) (vectors 16 36904) (vector-slots 8 740118 8269) (floats 8 99 184) (intervals 56 443 209) (buffers 992 51))
GC count: 1699 time: 34.51064284999998
Memory-use-counts: (20404199 27053 9965583 26169 1087666922 45065 30173 24290616)
   passed  48/53  tramp-test35-utf8-with-perl
GC: ((conses 16 368525 11147) (symbols 48 26107 0) (miscs 40 112 116) (strings 32 44796 14290) (string-bytes 1 1477623) (vectors 16 36901) (vector-slots 8 739801 9608) (floats 8 99 184) (intervals 56 444 208) (buffers 992 52))
GC count: 1763 time: 36.06389480499997
Memory-use-counts: (21134325 27788 10273401 26169 1129597041 46300 30175 25276270)
   passed  49/53  tramp-test35-utf8-with-stat
GC: ((conses 16 369452 11434) (symbols 48 26107 0) (miscs 40 114 114) (strings 32 44913 14421) (string-bytes 1 1490127) (vectors 16 36908) (vector-slots 8 740210 9199) (floats 8 99 184) (intervals 56 444 208) (buffers 992 53))
GC count: 1828 time: 37.548000696999985
Memory-use-counts: (21896846 28970 10581805 26169 1171667094 47513 30177 26281669)
Start timer foo<6> Thu Aug 24 12:41:05 2017
Stop timer foo<6> Thu Aug 24 12:41:05 2017
Start timer foo<3> Thu Aug 24 12:41:06 2017
Stop timer foo<3> Thu Aug 24 12:41:06 2017
Start action 0 foo<3> Thu Aug 24 12:41:06 2017
Stop action 0 foo<3> Thu Aug 24 12:41:07 2017
Start action 1 foo<3> Thu Aug 24 12:41:07 2017
Stop action 1 foo<3> Thu Aug 24 12:41:07 2017
Start action 0 foo<8> Thu Aug 24 12:41:07 2017
Stop action 0 foo<8> Thu Aug 24 12:41:07 2017
Start action 2 foo<3> Thu Aug 24 12:41:07 2017
Stop action 2 foo<3> Thu Aug 24 12:41:07 2017
Start action 0 foo<9> Thu Aug 24 12:41:07 2017
Stop action 0 foo<9> Thu Aug 24 12:41:07 2017
Start timer foo<8> Thu Aug 24 12:41:07 2017
Stop timer foo<8> Thu Aug 24 12:41:07 2017
Start action 0 foo<7> Thu Aug 24 12:41:07 2017
Stop action 0 foo<7> Thu Aug 24 12:41:08 2017
Start action 0 foo<2> Thu Aug 24 12:41:08 2017
Stop action 0 foo<2> Thu Aug 24 12:41:08 2017
Start action 0 foo Thu Aug 24 12:41:08 2017
Stop action 0 foo Thu Aug 24 12:41:08 2017
Start action 1 foo<8> Thu Aug 24 12:41:08 2017
Stop action 1 foo<8> Thu Aug 24 12:41:08 2017
Start action 1 foo Thu Aug 24 12:41:08 2017
Stop action 1 foo Thu Aug 24 12:41:08 2017
Start action 2 foo<8> Thu Aug 24 12:41:08 2017
Start timer foo<4> Thu Aug 24 12:41:08 2017
Stop timer foo<4> Thu Aug 24 12:41:08 2017
Stop action 2 foo<8> Thu Aug 24 12:41:08 2017
Start action 1 foo<7> Thu Aug 24 12:41:08 2017
Stop action 1 foo<7> Thu Aug 24 12:41:08 2017
Start action 2 foo<7> Thu Aug 24 12:41:08 2017
Stop action 2 foo<7> Thu Aug 24 12:41:08 2017
Start action 0 foo<10> Thu Aug 24 12:41:09 2017
Stop action 0 foo<10> Thu Aug 24 12:41:09 2017
Start action 1 foo<9> Thu Aug 24 12:41:09 2017
Stop action 1 foo<9> Thu Aug 24 12:41:09 2017
Start action 0 foo<6> Thu Aug 24 12:41:09 2017
Stop action 0 foo<6> Thu Aug 24 12:41:09 2017
Start action 2 foo Thu Aug 24 12:41:09 2017
Stop action 2 foo Thu Aug 24 12:41:09 2017
Start action 1 foo<10> Thu Aug 24 12:41:09 2017
Start timer foo<7> Thu Aug 24 12:41:09 2017
Stop timer foo<7> Thu Aug 24 12:41:09 2017
Stop action 1 foo<10> Thu Aug 24 12:41:09 2017
Start action 1 foo<2> Thu Aug 24 12:41:09 2017
Stop action 1 foo<2> Thu Aug 24 12:41:09 2017
Start action 0 foo<5> Thu Aug 24 12:41:09 2017
Stop action 0 foo<5> Thu Aug 24 12:41:10 2017
Start action 1 foo<5> Thu Aug 24 12:41:10 2017
Stop action 1 foo<5> Thu Aug 24 12:41:10 2017
Start action 0 foo<4> Thu Aug 24 12:41:10 2017
Stop action 0 foo<4> Thu Aug 24 12:41:10 2017
Start action 1 foo<6> Thu Aug 24 12:41:10 2017
Stop action 1 foo<6> Thu Aug 24 12:41:10 2017
Start action 2 foo<10> Thu Aug 24 12:41:10 2017
Stop action 2 foo<10> Thu Aug 24 12:41:10 2017
Start action 2 foo<6> Thu Aug 24 12:41:10 2017
Stop action 2 foo<6> Thu Aug 24 12:41:10 2017
Start timer foo<2> Thu Aug 24 12:41:10 2017
Stop timer foo<2> Thu Aug 24 12:41:10 2017
Start action 1 foo<4> Thu Aug 24 12:41:10 2017
Stop action 1 foo<4> Thu Aug 24 12:41:10 2017
Start action 2 foo<9> Thu Aug 24 12:41:10 2017
Stop action 2 foo<9> Thu Aug 24 12:41:10 2017
Start action 2 foo<4> Thu Aug 24 12:41:10 2017
Stop action 2 foo<4> Thu Aug 24 12:41:11 2017
Start action 2 foo<5> Thu Aug 24 12:41:11 2017
Stop action 2 foo<5> Thu Aug 24 12:41:11 2017
Start action 2 foo<2> Thu Aug 24 12:41:11 2017
Stop action 2 foo<2> Thu Aug 24 12:41:11 2017
Check Thu Aug 24 12:41:11 2017
   passed  50/53  tramp-test36-asynchronous-requests
GC: ((conses 16 371844 12671) (symbols 48 26113 0) (miscs 40 137 158) (strings 32 45126 14580) (string-bytes 1 1496079) (vectors 16 37079) (vector-slots 8 752632 13327) (floats 8 99 184) (intervals 56 444 208) (buffers 992 64))
GC count: 1905 time: 39.231900315999994
Memory-use-counts: (22823353 30085 10964701 26175 1224130163 48874 30185 27463297)
   passed  51/53  tramp-test37-recursive-load
GC: ((conses 16 371373 13018) (symbols 48 26113 0) (miscs 40 137 158) (strings 32 45002 14549) (string-bytes 1 1495065) (vectors 16 36900) (vector-slots 8 739568 17704) (floats 8 99 184) (intervals 56 443 209) (buffers 992 64))
GC count: 1906 time: 39.267056815
Memory-use-counts: (22824227 30086 10966094 26175 1224147401 48894 30185 27463843)
   passed  52/53  tramp-test38-remote-load-path
GC: ((conses 16 371390 13001) (symbols 48 26113 0) (miscs 40 137 158) (strings 32 45004 14547) (string-bytes 1 1495210) (vectors 16 36901) (vector-slots 8 739572 17700) (floats 8 99 184) (intervals 56 443 209) (buffers 992 64))
GC count: 1907 time: 39.288148545
Memory-use-counts: (22824596 30087 10966340 26175 1224157355 48909 30185 27464272)
   passed  53/53  tramp-test39-unload
GC: ((conses 16 366635 19526) (symbols 48 26107 7) (miscs 40 70 175) (strings 32 40411 18117) (string-bytes 1 1260035) (vectors 16 34529) (vector-slots 8 691861 47328) (floats 8 58 225) (intervals 56 442 210) (buffers 992 41))
GC count: 1909 time: 39.324882516
Memory-use-counts: (22980660 30089 10966609 26176 1224158707 48921 30185 27464315)

Ran 53 tests, 52 results as expected, 1 skipped (2017-08-24 12:41:12-0700)
1 expected failures

1 skipped results:
  SKIPPED  tramp-test31-vc-registered


[-- Attachment #3: Type: text/plain, Size: 205 bytes --]


And here are the messages I added to ert-run-test's loop:

(message "GC: %s" (garbage-collect))
(message "GC count: %s time: %s" gcs-done gc-elapsed)
(message "Memory-use-counts: %s" (memory-use-counts))

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2017-09-09 17:47 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-08-24 21:03 bug#28227: 26.0.50; Tramp tests are slow Gemini Lasswell
2017-08-25  8:04 ` Michael Albinus
     [not found]   ` <874lsok15a.fsf@runbox.com>
2017-08-31  2:26     ` npostavs
2017-08-31 14:46       ` Gemini Lasswell
2017-09-01 12:28         ` Michael Albinus
2017-09-04 22:43           ` Gemini Lasswell
2017-09-05  7:45             ` Michael Albinus
2017-09-09 16:27               ` Gemini Lasswell
2017-09-09 17:47                 ` Michael Albinus

Code repositories for project(s) associated with this public inbox

	https://git.savannah.gnu.org/cgit/emacs.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).