Performance problem first request

Aspose.Words Product Family
1

Hi,


I use API JAVA Aspose Word for update document.
At the first use, i have message Garbage Collector.
This query takes 108168 ms :
- new Document = 67517 ms
- save = 35360 ms

This issue affects only the first request.

My Settings
- Weblogic 10, java 5
- Aspose Word 5 13.4.0.0
- JVM MEmory -Xms512m -Xmx1024m
- Size doc : 25 kb


Message GC :
[INFO ][memory ] [YC#249] 1469.445-1469.774: YC 558324KB->443925KB (608760KB), 0.328 s, sum of pauses 327.457 ms, longest pause 327.457 ms.
[INFO ][memory ] [OC#44] 1470.468-1471.665: OC 573189KB->355659KB (608760KB), 1.197 s, sum of pauses 1191.379 ms, longest pause 1191.379 ms.
[INFO ][memory ] [YC#250] 1472.726-1472.968: YC 550868KB->464170KB (608760KB), 0.243 s, sum of pauses 242.407 ms, longest pause 242.407 ms.
[INFO ][memory ] [OC#45] 1473.825-1474.666: OC 574693KB->345051KB (654560KB), 0.841 s, sum of pauses 836.977 ms, longest pause 836.977 ms.
[INFO ][memory ] [YC#251] 1475.108-1475.263: YC 442336KB->399917KB (654560KB), 0.155 s, sum of pauses 155.026 ms, longest pause 155.026 ms.
[INFO ][memory ] [YC#252] 1475.624-1475.796: YC 472976KB->428354KB (654560KB), 0.172 s, sum of pauses 172.000 ms, longest pause 172.000 ms.
[INFO ][memory ] [YC#253] 1476.078-1476.266: YC 501889KB->461387KB (654560KB), 0.187 s, sum of pauses 186.823 ms, longest pause 186.823 ms.
[INFO ][memory ] [YC#254] 1476.748-1476.976: YC 534932KB->493333KB (654560KB), 0.227 s, sum of pauses 226.887 ms, longest pause 226.887 ms.
[INFO ][memory ] [YC#255] 1477.510-1477.641: YC 567071KB->526260KB (654560KB), 0.131 s, sum of pauses 131.088 ms, longest pause 131.088 ms.
[INFO ][memory ] [YC#256] 1478.066-1478.289: YC 598285KB->556431KB (654560KB), 0.224 s, sum of pauses 223.333 ms, longest pause 223.333 ms.
[INFO ][memory ] [YC#257] 1478.950-1479.213: YC 630099KB->654560KB (654560KB), 0.263 s, sum of pauses 262.946 ms, longest pause 262.946 ms.
[INFO ][memory ] [OC#46] 1479.213-1482.589: OC 654560KB->278830KB (654560KB), 3.376 s, sum of pauses 3366.315 ms, longest pause 3366.315 ms.
[INFO ][memory ] [YC#258] 1483.781-1484.112: YC 468301KB->385222KB (654560KB), 0.331 s, sum of pauses 330.564 ms, longest pause 330.564 ms.
[INFO ][memory ] [YC#259] 1484.921-1485.287: YC 526925KB->450115KB (654560KB), 0.367 s, sum of pauses 366.288 ms, longest pause 366.288 ms.
[INFO ][memory ] [YC#260] 1486.219-1486.549: YC 593085KB->510137KB (654560KB), 0.330 s, sum of pauses 329.765 ms, longest pause 329.765 ms.
[INFO ][memory ] [OC#47] 1487.644-1490.415: OC 639780KB->314213KB (622900KB), 2.771 s, sum of pauses 963.112 ms, longest pause 963.112 ms.
[INFO ][memory ] [YC#261] 1495.225-1495.456: YC 490794KB->388599KB (622900KB), 0.232 s, sum of pauses 190.289 ms, longest pause 190.289 ms.
[INFO ][memory ] [YC#262] 1496.242-1496.655: YC 524637KB->437664KB (622900KB), 0.413 s, sum of pauses 412.516 ms, longest pause 412.516 ms.
[INFO ][memory ] [YC#263] 1497.754-1498.225: YC 579647KB->504972KB (622900KB), 0.471 s, sum of pauses 470.943 ms, longest pause 470.943 ms.
[INFO ][memory ] [OC#48] 1498.251-1499.046: OC 513806KB->288230KB (654184KB), 0.796 s, sum of pauses 786.419 ms, longest pause 786.419 ms.
[INFO ][memory ] [YC#264] 1500.408-1500.408: YC 477078KB->394344KB (654184KB), 0.441 s, sum of pauses 246.069 ms, longest pause 246.069 ms.
[INFO ][memory ] [YC#265] 1501.191-1501.599: YC 535438KB->459272KB (654184KB), 0.408 s, sum of pauses 407.222 ms, longest pause 407.222 ms.
[INFO ][memory ] [YC#266] 1502.474-1502.835: YC 600908KB->526699KB (654184KB), 0.361 s, sum of pauses 360.681 ms, longest pause 360.681 ms.
[INFO ][memory ] [OC#49] 1502.978-1503.823: OC 577776KB->306033KB (654184KB), 0.845 s, sum of pauses 842.012 ms, longest pause 842.012 ms.
[INFO ][memory ] [YC#267] 1504.492-1504.804: YC 494612KB->410534KB (654184KB), 0.312 s, sum of pauses 311.617 ms, longest pause 311.617 ms.
[INFO ][memory ] [YC#268] 1505.355-1505.719: YC 551685KB->473938KB (654184KB), 0.364 s, sum of pauses 363.932 ms, longest pause 363.932 ms.
[INFO ][memory ] [YC#269] 1506.258-1506.721: YC 615282KB->535711KB (654184KB), 0.463 s, sum of pauses 462.375 ms, longest pause 462.375 ms.
[INFO ][memory ] [OC#50] 1507.661-1508.383: OC 548943KB->285511KB (608760KB), 0.722 s, sum of pauses 714.423 ms, longest pause 714.423 ms.
[INFO ][memory ] [YC#270] 1509.167-1509.380: YC 473512KB->389018KB (608760KB), 0.213 s, sum of pauses 213.120 ms, longest pause 213.120 ms.
[INFO ][memory ] [YC#271] 1510.194-1510.552: YC 530538KB->452739KB (608760KB), 0.359 s, sum of pauses 219.117 ms, longest pause 219.117 ms.
[INFO ][memory ] [OC#51] 1511.233-1512.146: OC 593202KB->358771KB (685692KB), 0.913 s, sum of pauses 909.625 ms, longest pause 909.625 ms.
[INFO ][memory ] [YC#272] 1512.447-1512.594: YC 452223KB->410049KB (685692KB), 0.147 s, sum of pauses 147.207 ms, longest pause 147.207 ms.
[INFO ][memory ] [YC#273] 1512.817-1512.952: YC 481166KB->442741KB (685692KB), 0.135 s, sum of pauses 134.944 ms, longest pause 134.944 ms.
[INFO ][memory ] [YC#274] 1513.290-1513.543: YC 514195KB->475908KB (685692KB), 0.254 s, sum of pauses 252.821 ms, longest pause 252.821 ms.
[INFO ][memory ] [YC#275] 1513.856-1514.017: YC 545912KB->506600KB (685692KB), 0.161 s, sum of pauses 161.330 ms, longest pause 161.330 ms.
[INFO ][memory ] [YC#276] 1514.265-1514.394: YC 577745KB->539204KB (685692KB), 0.129 s, sum of pauses 128.587 ms, longest pause 128.587 ms.
[INFO ][memory ] [YC#277] 1514.874-1515.067: YC 609892KB->572600KB (685692KB), 0.193 s, sum of pauses 192.854 ms, longest pause 192.854 ms.
[INFO ][memory ] [YC#278] 1515.642-1515.788: YC 643753KB->606357KB (685692KB), 0.146 s, sum of pauses 145.771 ms, longest pause 145.771 ms.
[INFO ][memory ] [YC#279] 1516.004-1516.152: YC 677865KB->685692KB (685692KB), 0.148 s, sum of pauses 147.342 ms, longest pause 147.342 ms.
[INFO ][memory ] [OC#52] 1516.159-1519.437: OC 685692KB->322490KB (685692KB), 3.278 s, sum of pauses 3267.753 ms, longest pause 3267.753 ms.
[INFO ][memory ] [YC#280] 1520.985-1521.198: YC 521246KB->433559KB (685692KB), 0.213 s, sum of pauses 212.517 ms, longest pause 212.517 ms.
[INFO ][memory ] [YC#281] 1522.167-1522.773: YC 583709KB->494433KB (685692KB), 0.606 s, sum of pauses 605.357 ms, longest pause 605.357 ms.
[INFO ][memory ] [YC#282] 1523.621-1523.966: YC 644316KB->562440KB (685692KB), 0.345 s, sum of pauses 344.525 ms, longest pause 344.525 ms.
[INFO ][memory ] [OC#53] 1523.972-1524.556: OC 564020KB->280762KB (650548KB), 0.584 s, sum of pauses 579.638 ms, longest pause 579.638 ms.
[INFO ][memory ] [YC#283] 1525.283-1525.770: YC 480410KB->391855KB (650548KB), 0.487 s, sum of pauses 249.069 ms, longest pause 249.069 ms.
[INFO ][memory ] [YC#284] 1526.860-1527.119: YC 541898KB->460617KB (650548KB), 0.259 s, sum of pauses 258.431 ms, longest pause 258.431 ms.
[INFO ][memory ] [YC#285] 1527.984-1528.385: YC 610675KB->525987KB (650548KB), 0.400 s, sum of pauses 400.148 ms, longest pause 400.148 ms.
[INFO ][memory ] [OC#54] 1528.411-1529.325: OC 535055KB->283515KB (645312KB), 0.913 s, sum of pauses 909.846 ms, longest pause 909.846 ms.
[INFO ][memory ] [YC#286] 1530.294-1530.899: YC 483462KB->395701KB (645312KB), 0.606 s, sum of pauses 343.568 ms, longest pause 343.568 ms.
[INFO ][memory ] [YC#287] 1531.816-1532.036: YC 545626KB->458371KB (645312KB), 0.219 s, sum of pauses 219.128 ms, longest pause 219.128 ms.
[INFO ][memory ] [YC#288] 1532.866-1533.102: YC 608382KB->645312KB (645312KB), 0.237 s, sum of pauses 236.406 ms, longest pause 236.406 ms.
[INFO ][memory ] [OC#55] 1533.105-1534.529: OC 645312KB->279925KB (645312KB), 1.424 s, sum of pauses 1418.267 ms, longest pause 1418.267 ms.
[INFO ][memory ] [YC#289] 1535.542-1536.133: YC 480255KB->391674KB (645312KB), 0.591 s, sum of pauses 323.765 ms, longest pause 323.765 ms.




2

Hi,


Thanks for your inquiry. Could you please attach your input Word document and source code here for testing? I will investigate the issue on my side and provide you more information.

Best regards,
3

Hi,


I send you the ZIP file (source code, document).
I executed class on Eclipse. We have the same behavior with Weblogic Server only with less time.

The result :
StartConvert
Document Creation time = 600
Document Total time = 3340
EndConvert
StartConvert
Document Creation time = 10
Document Total time = 132
EndConvert
StartConvert
Document Creation time = 18
Document Total time = 110
EndConvert
StartConvert
Document Creation time = 7
Document Total time = 123
EndConvert

Best regards,
4
Hi,

Thanks for your inquiry. I have tested the scenario and have managed to reproduce the same problem on my side. For the sake of correction, I have logged this problem in our issue tracking system as WORDSJAVA-722. Our development team will further look into the details of this problem and we will keep you updated on the status of correction. We apologize for your inconvenience.

Best regards,
5

Hi,


Thanks for your response, do you have a date of correction ?

Best regards,
6

Hi,


Thanks for your inquiry. Unfortunately, this issue is not resolved yet. Your issue is currently pending for analysis and unfortunately at the moment we cannot provide you any reliable estimate. We will inform you via this forum thread as soon as this issue is resolved. We apologize for any inconvenience.

Best regards,
7

Hi,


It is normal Java behavior known as “warm-up time”. On the first call JRE loads classes. In few subsequent calls it performs JIT optimization (if it enabled).


You can get more info and few tweaks if you google “java warm-up time”.


The issue is closed as "not a bug".


Best regards,