Community
Participate
Working Groups
While running the refactoring RenameTypeTest on I20040210 I noticed that they take a very long time to finish. Some tracing showed that most of the time is spent in HistroySore.copyHistory. The numbers are: Time spent to copy histroy: 50 ms Time spent to copy histroy: 80 ms Time spent to copy histroy: 171 ms Time spent to copy histroy: 121 ms Time spent to copy histroy: 121 ms Time spent to copy histroy: 140 ms Time spent to copy histroy: 300 ms Time spent to copy histroy: 371 ms Time spent to copy histroy: 411 ms Time spent to copy histroy: 501 ms Time spent to copy histroy: 20 ms Time spent to copy histroy: 20 ms Time spent to copy histroy: 30 ms Time spent to copy histroy: 30 ms Time spent to copy histroy: 40 ms Time spent to copy histroy: 50 ms Time spent to copy histroy: 60 ms Time spent to copy histroy: 922 ms Time spent to copy histroy: 1323 ms Time spent to copy histroy: 1985 ms Time spent to copy histroy: 1674 ms Time spent to copy histroy: 1784 ms Time spent to copy histroy: 1824 ms Time spent to copy histroy: 1904 ms Time spent to copy histroy: 2024 ms Time spent to copy histroy: 2074 ms Time spent to copy histroy: 2085 ms Time spent to copy histroy: 2215 ms Time spent to copy histroy: 2285 ms Time spent to copy histroy: 2354 ms Time spent to copy histroy: 2496 ms Time spent to copy histroy: 2576 ms Time spent to copy histroy: 2645 ms Time spent to copy histroy: 2716 ms Time spent to copy histroy: 2795 ms Time spent to copy histroy: 3006 ms Time spent to copy histroy: 3077 ms Time spent to copy histroy: 3457 ms Time spent to copy histroy: 3337 ms Time spent to copy histroy: 3597 ms Time spent to copy histroy: 3647 ms Time spent to copy histroy: 3768 ms Time spent to copy histroy: 4078 ms Time spent to copy histroy: 4308 ms Time spent to copy histroy: 4199 ms Time spent to copy histroy: 4209 ms Time spent to copy histroy: 5101 ms Time spent to copy histroy: 4309 ms Time spent to copy histroy: 4479 ms Time spent to copy histroy: 4620 ms Time spent to copy histroy: 4769 ms Time spent to copy histroy: 4910 ms Time spent to copy histroy: 4921 ms Time spent to copy histroy: 5081 ms Time spent to copy histroy: 5210 ms Time spent to copy histroy: 5041 ms Time spent to copy histroy: 5372 ms Time spent to copy histroy: 2184 ms Time spent to copy histroy: 2225 ms Time spent to copy histroy: 5822 ms Time spent to copy histroy: 5872 ms Time spent to copy histroy: 5802 ms Time spent to copy histroy: 6162 ms Time spent to copy histroy: 6303 ms Time spent to copy histroy: 6143 ms Time spent to copy histroy: 6343 ms Time spent to copy histroy: 6613 ms Time spent to copy histroy: 6915 ms Time spent to copy histroy: 6654 ms Time spent to copy histroy: 6764 ms Time spent to copy histroy: 6964 ms Time spent to copy histroy: 3147 ms Time spent to copy histroy: 20 ms Time spent to copy histroy: 7255 ms Time spent to copy histroy: 7225 ms The time was measured by surrounding the code of the copyHistory method with the following code: long start= System.currentTimeMillis(); try { } finally { System.out.println("Time spent to copy histroy: " + (System.currentTimeMillis() - start) + " ms"); }
I used build 200402101600 both for development and as a target.
Perhaps related to bug 28603. Note that referenced test case is: org.eclipse.jdt.ui.tests.refactoring.RenameTypeTests
I am seeing this as well in refactorings that change the name of a compilation unit. Are there plans to do something for M7 ?
It seems that the performace problem only shows up when using VM java version "1.4.1" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1) Classic VM (build 1.4.1, J2RE 1.4.1 IBM Windows 32 build cn1411-20031212 (JIT enabled: jitc))
Here are my times for when using RC1 + JDT.UI.TESTS from HEAD with Sun and IBM VMs: Sun JDK 1.4.2_03: Time to copy history: 60 Time to copy history: 60 Time to copy history: 80 Time to copy history: 50 Time to copy history: 50 Time to copy history: 71 Time to copy history: 110 Time to copy history: 80 Time to copy history: 120 Time to copy history: 171 Time to copy history: 30 Time to copy history: 20 Time to copy history: 20 Time to copy history: 20 Time to copy history: 20 Time to copy history: 30 Time to copy history: 20 Time to copy history: 280 Time to copy history: 250 Time to copy history: 320 Time to copy history: 641 Time to copy history: 331 Time to copy history: 320 Time to copy history: 361 Time to copy history: 370 Time to copy history: 741 Time to copy history: 360 Time to copy history: 430 Time to copy history: 421 Time to copy history: 741 Time to copy history: 491 Time to copy history: 501 Time to copy history: 781 Time to copy history: 561 Time to copy history: 590 Time to copy history: 871 Time to copy history: 581 Time to copy history: 881 Time to copy history: 671 Time to copy history: 641 Time to copy history: 972 Time to copy history: 671 Time to copy history: 962 Time to copy history: 731 Time to copy history: 1031 Time to copy history: 711 Time to copy history: 1071 Time to copy history: 781 Time to copy history: 1111 Time to copy history: 832 Time to copy history: 1291 Time to copy history: 872 Time to copy history: 1241 Time to copy history: 1232 Time to copy history: 951 Time to copy history: 1302 Time to copy history: 1011 Time to copy history: 401 Time to copy history: 380 Time to copy history: 1362 Time to copy history: 1422 Time to copy history: 1382 Time to copy history: 1092 Time to copy history: 1482 Time to copy history: 1192 Time to copy history: 1503 Time to copy history: 1563 Time to copy history: 1622 Time to copy history: 1622 Time to copy history: 1633 Time to copy history: 1312 Time to copy history: 501 Time to copy history: 20 Time to copy history: 2103 Time to copy history: 1832 Time to copy history: 1763 Time to copy history: 1772 Time to copy history: 1763 Time to copy history: 1492 Time to copy history: 1853 Time to copy history: 1832 Time to copy history: 1873 Time to copy history: 1933 Time to copy history: 1913 Time to copy history: 1562 Time to copy history: 20 Time to copy history: 1973 Time to copy history: 1923 Time to copy history: 1863 Time to copy history: 1942 Time to copy history: 1983 Time to copy history: 1993 Time to copy history: 2313 Time to copy history: 2013 Time to copy history: 2053 Time to copy history: 2053 Time to copy history: 2053 Time to copy history: 2513 Time to copy history: 2204 Time to copy history: 2363 Time to copy history: 2223 Time to copy history: 2223 Time to copy history: 2303 Time to copy history: 2334 Time to copy history: 2714 Time to copy history: 2274 Time to copy history: 2363 Time to copy history: 2383 Time to copy history: 2424 Time to copy history: 2313 Time to copy history: 2404 Time to copy history: 2744 Time to copy history: 2474 Time to copy history: 2544 Time to copy history: 2874 Time to copy history: 2924 Time to copy history: 2764 Time to copy history: 3094 Time to copy history: 3165 Time to copy history: 3124 Time to copy history: 2815 Time to copy history: 2954 Time to copy history: 2643 Time to copy history: 2694 Time to copy history: 2744 Time to copy history: 3034 Time to copy history: 2764 Time to copy history: 2724 Time to copy history: 3155 Time to copy history: 2854 ==================================================== J2RE 1.4.1 IBM Windows 32 build cn1411-20040511 Time to copy history: 80 Time to copy history: 80 Time to copy history: 100 Time to copy history: 60 Time to copy history: 80 Time to copy history: 60 Time to copy history: 60 Time to copy history: 190 Time to copy history: 70 Time to copy history: 81 Time to copy history: 10 Time to copy history: 20 Time to copy history: 20 Time to copy history: 20 Time to copy history: 20 Time to copy history: 10 Time to copy history: 20 Time to copy history: 301 Time to copy history: 240 Time to copy history: 350 Time to copy history: 360 Time to copy history: 331 Time to copy history: 250 Time to copy history: 331 Time to copy history: 400 Time to copy history: 270 Time to copy history: 370 Time to copy history: 351 Time to copy history: 391 Time to copy history: 431 Time to copy history: 531 Time to copy history: 470 Time to copy history: 411 Time to copy history: 361 Time to copy history: 551 Time to copy history: 540 Time to copy history: 460 Time to copy history: 671 Time to copy history: 511 Time to copy history: 561 Time to copy history: 521 Time to copy history: 581 Time to copy history: 581 Time to copy history: 611 Time to copy history: 541 Time to copy history: 561 Time to copy history: 621 Time to copy history: 721 Time to copy history: 591 Time to copy history: 621 Time to copy history: 851 Time to copy history: 701 Time to copy history: 711 Time to copy history: 781 Time to copy history: 701 Time to copy history: 771 Time to copy history: 811 Time to copy history: 170 Time to copy history: 280 Time to copy history: 871 Time to copy history: 831 Time to copy history: 831 Time to copy history: 811 Time to copy history: 901 Time to copy history: 881 Time to copy history: 951 Time to copy history: 962 Time to copy history: 942 Time to copy history: 951 Time to copy history: 941 Time to copy history: 991 Time to copy history: 331 Time to copy history: 20 Time to copy history: 921 Time to copy history: 981 Time to copy history: 1031 Time to copy history: 1021 Time to copy history: 1051 Time to copy history: 1062 Time to copy history: 1191 Time to copy history: 1102 Time to copy history: 1162 Time to copy history: 1132 Time to copy history: 1191 Time to copy history: 1172 Time to copy history: 20 Time to copy history: 1191 Time to copy history: 1091 Time to copy history: 1222 Time to copy history: 1242 Time to copy history: 1271 Time to copy history: 1232 Time to copy history: 1302 Time to copy history: 1302 Time to copy history: 1312 Time to copy history: 1593 Time to copy history: 1302 Time to copy history: 1523 Time to copy history: 1281 Time to copy history: 1372 Time to copy history: 1512 Time to copy history: 1472 Time to copy history: 1653 Time to copy history: 1502 Time to copy history: 1462 Time to copy history: 1392 Time to copy history: 1372 Time to copy history: 1432 Time to copy history: 1502 Time to copy history: 1452 Time to copy history: 1382 Time to copy history: 1472 Time to copy history: 1752 Time to copy history: 1533 Time to copy history: 1552 Time to copy history: 1572 Time to copy history: 1572 Time to copy history: 1532 Time to copy history: 1572 Time to copy history: 1472 Time to copy history: 1593 Time to copy history: 1582 Time to copy history: 1673 Time to copy history: 1642 Time to copy history: 1712 Time to copy history: 1712 Time to copy history: 1653 Time to copy history: 1702 Time to copy history: 1713 Time to copy history: 1703
I'm going to close this for now since performance with the latest IBM VM has greatly improved. We'll keep an eye on it though and re-open if it becomes a problem again.
But these numbers still look bad. Its OK for me to push the PR to 3.1 but closing as works for me seems strange to me.
Agreed. I was incorrectly assuming that there was a lot of history for the files but after re-running your tests with more debug information it looks like there is only one file state per file which makes the timings strange. Re-opening for investigation. I'll mark as 3.1 but include it in the performance work in the next couple of weeks.
Rafael, can you please check out these numbers against the new history store implementation? Thanks.
This scenario (moving history from a resource to another in the same folder) is the best case for copyHistory in the new implementation (0 to 31ms). Dirk, what would be a good refactoring test case that would cause history to be copied accross different folders?
Moving a package. This actually copies the files
Would that be org.eclipse.jdt.ui.tests.refactoring.CopyPackageChangeTest?
er... probably not, you said "*moving* a package"... what test class would that be then?
They are part of the move tests. But you could run the rename package tests as well. Renaming a package moves/copies files in the package.
According do Dirk, the exact test suite is org.eclipse.jdt.ui.tests.refactoring.RenamePackageTests. That test does not create a lot of history, so it is not a good test. Anyway, we have our own performance tests for the local history. Since the original issue reported here has been addressed since the new implementation for the history store was enabled by default (M4), I am going to close this one.
