Performance issues identified in converting .docx file to PDF

Hi,
We are using aspose.words for java for converting the word document files(2003xml, .docx, .doc) to PDF. The process is extremely slow and eating up all our CPU resources. We are using 18.12 jar at this point and the estimated overhead on the CPU is around 20% for small number of users(~around 10) and smaller sized documents(~50 KB). However, as the no.of users increase and the size of documents increases, the CPU overhead is increasing alarmingly and for a 50 user and 300 KB size document scenario, aspose API’s only are using around 60% of our JVM CPU.
The specific packages that are using maximum of the CPU time are
com.aspose.words
and com.aspose.words.internal.

In this we also have identified some methods like com.aspose.words.internal.zzZF which take more resources.

This is not acceptable for our product since the average no.of users for the application will be around 150 users.

So, what we want to understand from aspose is,

  1. What is the recommended configuration of system needed for Aspose to work for higher payload. Any sizing recommendations, memory requirements or CPU requirements?
  2. The KPI’s for Aspose.words for java.
  3. What are you recommendations on the size of the documents supported and what is your understanding of how much CPU utilization will be required?

Please treat this as a very high priority issue since the system is coming down when this feature is being used impacting multiple users.
Thanks,
Kundana.

1 Like

@Kundana

Thanks for your inquiry. Please note that performance and memory usage all depend on complexity and size of the documents you are generating.

In terms of memory, Aspose.Words does not have any limitations. If you are loading huge Word documents into Aspose.Words’ DOM, more memory would be required. This is because during processing, the document needs to be held wholly in memory. Usually, Aspose.Words needs 10 times more memory than the original document size to build a DOM in the memory.

We suggest you please use SaveOptions.MemoryOptimization property to optimize the memory performance. Setting this option to true can significantly decrease memory consumption while saving large documents at the cost of slower saving time. Hope this helps you.

To precise what my colleague Kundana explained, our main concern is not in particular the memory consumption but the CPU utilization. A performance evaluation of Aspose.Words for Java in a multi-threaded context that we’ve done has shown that CPU utilization is far beyond our expectations for the relative small number of users (50-150) and small document size (300KB, no images/macros so mainly text only). For that reason, with the questions Kundana posted we’re attempting to understand better what we can expected from Aspose.Words for Java, and further more what best practices you can share with us.

@PieterB

Thanks for your inquiry. Please attach the following resources here for testing:

  • Your input Word documents.
  • Please create a simple Java application ( source code without compilation errors ) that helps us to reproduce your problem on our end and attach it here for testing.

As soon as you get these pieces of information ready, we will start investigation into your issue and provide you more information. Thanks for your cooperation.

PS: To attach these resources, please zip and upload them.

@tahir.manzoor

I am attaching a simple java class and 2 different document we have used to convert to pdf. We see that the CPU utilization is 3 times more for the 300 KB file compared to the other file. Please let us know what we can do to have optimum cpu utilization here.
Aspose testcase.zip (313.9 KB)
Thanks,
Kundana.

@Kundana

Thanks for sharing the code and documents.

It is quite difficult to answer such questions because CPU performance and memory usage all depend on complexity and size of the documents you are loading/generating.

It hardly depends on local environment. It can be completely different for a server that generates thousands documents 24/7 or for a local PC that generate only the one document by demand.

Another performance option is to use all processor’s cores. If you have, for instance, 8 virtual cores and 8000 documents it is better to instantiate 8 threads that will handle 1000 document each. The result will be about 5 time faster than processing all 8000 documents in the single thread.

Also, you should have enough heap space to exclude swapping. Another very important thing – fast disks. Changing HDD to SSD can rise performance twice or even more depending on quantity of disk IO operations.

Hope this answers your query. Please let us know if you have any more queries.

@tahir.manzoor
Did you run that test case. For your case, how much time dd the file take to complete? Can you give us a comparison of the memory and cpu time taken for attached 2 files?test files.zip (312.2 KB)

No, I think we are still not clear on what we need to do. Is it possible to have a quick call with your team to understand the action items?

@Kundana

We have tested the scenario using the latest version of Aspose.Words for Java 19.3 and have not found CPU performance issue. Please try the latest version of Aspose.Words for Java 19.3 and let us know how it goes on your side.

Please note that we only provide support via forum.

We will test with this and update you.

Even on paid support, you do not have an on call support? All your support is via forum?

@Kundana

Yes, we provide support only via forums.

Here are few more details from our testing. Converting the document to PDF file.
As mentioned above it is CPU intensive. We have uptaken the latest 19.3 patch and noticed no performance improvement.

Small Document Conversion : Sampledocumentwithmixedformat.docx.

The conversion took more than 15secs with average 10% CPU usage. max 20%

11:17:02 PM CPU %user %nice %system %iowait %steal %idle
11:17:17 PM all 8.13 0 3.66 13.82 0 74.39
11:17:15 PM all 1.02 0 0.41 0 0 98.57
11:17:16 PM all 0.41 0 0.41 0.61 0.2 98.37
11:17:17 PM all 8.13 0 3.66 13.82 0 74.39
11:17:18 PM all 3.66 0 1.22 17.28 0.41 77.44
11:17:19 PM all 9.61 0 2.04 14.93 0 73.42
11:17:20 PM all 7.74 0 3.05 14.66 0.2 74.34
11:17:21 PM all 5.91 0 1.43 16.09 0.41 76.17
11:17:22 PM all 10.22 0 5.73 15.75 0 68.3
11:17:23 PM all 19.18 0 4.69 5.31 0.2 70.61
11:17:24 PM all 8.15 0 2.24 11 0.2 78.41
11:17:25 PM all 17.89 0 2.24 12.4 0.2 67.28
11:17:26 PM all 19.43 0 1.64 8.79 0.2 69.94
11:17:27 PM all 4.24 0 1.01 16.57 0.2 77.98
11:17:28 PM all 8.96 0 1.83 14.46 0.2 74.54
11:17:29 PM all 4.1 0 1.43 20.29 0.2 73.98
11:17:30 PM all 20.2 0 3.88 6.73 0 69.18
11:17:31 PM all 2.85 0 0.81 6.5 0.2 89.63
11:17:32 PM all 0.2 0 0.2 0 0.2 99.39
11:17:33 PM all 0.61 0 0.2 0 0 99.19

the above details for small document(55kb) conversion in a single execution.

Big document conversion : 190 pages.docx

The conversion took more than 15secs with average 35% CPU usage. max:57%.

7:47:16 PM CPU %user %nice %system %iowait %steal %idle
7:47:34 PM all 0.4 0 0.2 0.4 0.2 98.79
7:47:35 PM all 0.2 0 0.2 0 0 99.59
7:47:36 PM all 0.2 0 0.2 0 0 99.59
7:47:37 PM all 3.05 0 1.63 3.25 0.2 91.87
7:47:38 PM all 26.87 0 5.45 0.4 0.2 67.07
7:47:39 PM all 20.28 0 5.68 0 0 74.04
7:47:40 PM all 27.94 0 4.05 1.21 0.2 66.6
7:47:41 PM all 49.49 0 4.06 1.42 0.2 44.83
7:47:42 PM all 40.04 0 4.27 1.02 0.2 54.47
7:47:43 PM all 46.37 0 2.82 0.2 0.2 50.4
7:47:44 PM all 57.89 0 2.23 0 0.2 39.68
7:47:45 PM all 41.5 0 2.43 1.62 0 54.45
7:47:46 PM all 45.56 0 1.21 0.4 0.2 52.62
7:47:47 PM all 56.45 0 3.83 0.2 0.2 39.31
7:47:48 PM all 51.72 0 2.43 1.22 0 44.62
7:47:49 PM all 28.4 0 1.83 0 0.2 69.57
7:47:50 PM all 32.45 0 2.43 0 0 65.11
7:47:51 PM all 3.46 0 1.63 0 0.2 94.72
7:47:52 PM all 0.2 0 0.61 4.67 0.2 94.31
7:47:53 PM all 0.2 0 0.2 1.22 0 98.37

Collected a CPU profile data for the small document single execution

We have noticed that code executed in 20 process threads

-bash-4.1$ ps -T 14833
PID SPID TTY STAT TIME COMMAND
14833 14833 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14834 pts/0 Rl+ 3:46 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14835 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14836 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14837 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14838 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14839 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14840 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14841 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14842 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14843 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14844 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14845 pts/0 Sl+ 0:01 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14846 pts/0 Sl+ 0:01 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14847 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14848 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14897 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14898 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14899 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l
14833 14974 pts/0 Sl+ 0:00 java -agentlib:hprof=cpu=times -cp /u01/R122_EBS/fs2/EBSapps/comn/util/jdk32/l

Profile Information

Rank Self Accumulate count Trace Method
17 0.28% 72.13% 341164 375164 com.aspose.words.internal.zz1Y.read
79 0.07% 80.94% 77975 375162 com.aspose.words.internal.zz1Y.read
36 0.16% 76.42% 421331 375157 com.aspose.words.internal.zz1Y.zzI
345 0.01% 86.96% 1 381944 com.aspose.words.internal.zz27.zzU
350 0.01% 87.01% 1 381984 com.aspose.words.internal.zz27.zzU
244 0.02% 85.69% 39230 374487 com.aspose.words.internal.zz6T.read
276 0.01% 86.15% 36937 408582 com.aspose.words.internal.zz6T.writeByte
22 0.26% 73.49% 335739 375171 com.aspose.words.internal.zz6U.read
83 0.06% 81.19% 76548 375163 com.aspose.words.internal.zz6U.read
32 0.20% 75.68% 259076 382831 com.aspose.words.internal.zz6Y.zzUB
61 0.09% 79.55% 111362 388584 com.aspose.words.internal.zz6Y.zzUB
87 0.05% 81.42% 64772 414378 com.aspose.words.internal.zz6Y.zzUB
228 0.02% 85.43% 22431 374430 com.aspose.words.internal.zz6Y.zzUB
245 0.02% 85.71% 20298 388608 com.aspose.words.internal.zz6Y.zzUB
29 0.21% 75.07% 259076 382832 com.aspose.words.internal.zz6Y.zzYj
62 0.09% 79.64% 111362 388585 com.aspose.words.internal.zz6Y.zzYj
91 0.05% 81.63% 64772 414379 com.aspose.words.internal.zz6Y.zzYl
257 0.01% 85.89% 20298 388609 com.aspose.words.internal.zz6Y.zzYl
173 0.02% 84.32% 1 388590 com.aspose.words.internal.zz9H.
80 0.07% 81.01% 55681 388589 com.aspose.words.internal.zz9I.
262 0.01% 85.96% 1 382027 com.aspose.words.internal.zz9V.
89 0.05% 81.53% 3 414388 com.aspose.words.internal.zzAQ.zzZ
78 0.07% 80.88% 57133 383105 com.aspose.words.internal.zzAU.zzZ
175 0.02% 84.36% 57133 383099 com.aspose.words.internal.zzAW.
167 0.02% 84.17% 57133 383106 com.aspose.words.internal.zzAW.zzEM
206 0.02% 85.03% 57133 383100 com.aspose.words.internal.zzAW.zzGH
290 0.01% 86.33% 1010 405944 com.aspose.words.internal.zzB4.zzYs
281 0.01% 86.22% 17073 382396 com.aspose.words.internal.zzC2.get
250 0.02% 85.78% 7429 372775 com.aspose.words.internal.zzC2.set
96 0.05% 81.86% 53398 307132 com.aspose.words.internal.zzC2.zzVm
214 0.02% 85.18% 13902 382922 com.aspose.words.internal.zzC3.add
203 0.02% 84.97% 57136 383094 com.aspose.words.internal.zzC3.getCount
52 0.12% 78.58% 100364 388617 com.aspose.words.internal.zzC3.set
216 0.02% 85.22% 13902 382909 com.aspose.words.internal.zzC3.set
169 0.02% 84.22% 57133 383095 com.aspose.words.internal.zzC3.zzVn
192 0.02% 84.74% 57133 383096 com.aspose.words.internal.zzC3.zzX2
111 0.04% 82.49% 100364 388616 com.aspose.words.internal.zzC3.zzY
105 0.04% 82.26% 6702 408455 com.aspose.words.internal.zzE4.write
121 0.03% 82.85% 10266 408776 com.aspose.words.internal.zzE4.write
148 0.03% 83.68% 6150 413308 com.aspose.words.internal.zzE4.write
267 0.01% 86.03% 3075 413313 com.aspose.words.internal.zzE4.write
317 0.01% 86.65% 1029 413181 com.aspose.words.internal.zzE4.write
347 0.01% 86.98% 5110 409071 com.aspose.words.internal.zzE4.write
109 0.04% 82.42% 1079 409323 com.aspose.words.internal.zzED.zzW
348 0.01% 86.99% 2158 409067 com.aspose.words.internal.zzED.zzY
334 0.01% 86.84% 1079 409011 com.aspose.words.internal.zzGK.zzZ
225 0.02% 85.38% 7591 408448 com.aspose.words.internal.zzIC.zzF
316 0.01% 86.64% 8098 408370 com.aspose.words.internal.zzIC.zzZZ
114 0.04% 82.61% 31 383107 com.aspose.words.internal.zzMM.resize
102 0.04% 82.13% 57133 383104 com.aspose.words.internal.zzMM.set
97 0.05% 81.90% 57133 383103 com.aspose.words.internal.zzMM.zzZ
94 0.05% 81.77% 64772 414384 com.aspose.words.internal.zzMU.add
160 0.03% 84.00% 64772 414383 com.aspose.words.internal.zzMU.ensureCapacity
142 0.03% 83.51% 3 382837 com.aspose.words.internal.zzPT.
151 0.03% 83.77% 3 414319 com.aspose.words.internal.zzPT.
180 0.02% 84.48% 57133 383098 com.aspose.words.internal.zzPT.zzXc
65 0.09% 79.90% 64769 382836 com.aspose.words.internal.zzPU.
70 0.08% 80.31% 64769 414318 com.aspose.words.internal.zzPU.
129 0.03% 83.12% 1079 409263 com.aspose.words.internal.zzTO.zzZ
138 0.03% 83.40% 4 382924 com.aspose.words.internal.zzVU.zzX
92 0.05% 81.67% 1 388625 com.aspose.words.internal.zzVW.zzZ
98 0.05% 81.95% 1 414329 com.aspose.words.internal.zzVW.zzZ
33 0.20% 75.87% 3 383110 com.aspose.words.internal.zzVZ.zzZ
278 0.01% 86.18% 30 304890 com.aspose.words.internal.zzWI$zzZ.zzZ
172 0.02% 84.29% 64772 414380 com.aspose.words.internal.zzX.zzV
90 0.05% 81.58% 64772 414381 com.aspose.words.internal.zzX.zzW
246 0.02% 85.72% 20298 388611 com.aspose.words.internal.zzX.zzW
59 0.10% 79.36% 259076 382833 com.aspose.words.internal.zzX.zzY
106 0.04% 82.30% 111362 388586 com.aspose.words.internal.zzX.zzY
30 0.21% 75.28% 259076 382834 com.aspose.words.internal.zzX.zzZ
60 0.10% 79.46% 83618 303361 com.aspose.words.internal.zzX.zzZ
66 0.08% 79.98% 111362 388587 com.aspose.words.internal.zzX.zzZ
319 0.01% 86.68% 9440 382897 com.aspose.words.internal.zzYM.zzYi
14 0.31% 71.26% 259076 382835 com.aspose.words.internal.zzYM.zzYj
44 0.14% 77.54% 111362 388588 com.aspose.words.internal.zzYM.zzYj
68 0.08% 80.15% 64772 414382 com.aspose.words.internal.zzYM.zzYl
164 0.02% 84.10% 20298 388612 com.aspose.words.internal.zzYM.zzYl
352 0.01% 87.03% 19 357247 com.aspose.words.internal.zzZ3Y.zzZ
119 0.04% 82.79% 100364 388615 com.aspose.words.internal.zzZF.binarySearch
181 0.02% 84.50% 60767 307131 com.aspose.words.internal.zzZF.binarySearch
310 0.01% 86.57% 3 363735 com.aspose.words.internal.zzZFT.update
279 0.01% 86.19% 29891 363733 com.aspose.words.internal.zzZK8.zzE
226 0.02% 85.40% 38560 357134 com.aspose.words.internal.zzZK8.zzg
289 0.01% 86.32% 38560 357133 com.aspose.words.internal.zzZK8.zzh
130 0.03% 83.15% 1867 363734 com.aspose.words.internal.zzZK8.zzYXB
158 0.03% 83.95% 190 356840 com.aspose.words.internal.zzZKO.zzYXB
238 0.02% 85.60% 124 356970 com.aspose.words.internal.zzZKO.zzYXB
305 0.01% 86.51% 32688 358973 com.aspose.words.internal.zzZN3.zzXl
353 0.01% 87.04% 28392 358987 com.aspose.words.internal.zzZN3.zzXl
251 0.02% 85.80% 8527 313623 com.aspose.words.internal.zzZXD.zzY
149 0.03% 83.71% 8527 313624 com.aspose.words.internal.zzZY8.zzZ2
275 0.01% 86.14% 1820 313650 com.aspose.words.internal.zzZYI.zzZ9
309 0.01% 86.56% 30630 313622 com.aspose.words.internal.zzZYN.isNameChar
292 0.01% 86.36% 12590 382397 com.aspose.words.zz6.zzTA
154 0.03% 83.85% 22343 382395 com.aspose.words.zz6.zzVm
166 0.02% 84.15% 18478 307133 com.aspose.words.zz6.zzVm
208 0.02% 85.07% 53398 307130 com.aspose.words.zz6.zzy6
118 0.04% 82.75% 160 377943 com.aspose.words.zzWS.zzZ
84 0.06% 81.25% 23471 393813 com.aspose.words.zzY4.zzuo
155 0.03% 83.87% 70413 393809 com.aspose.words.zzY5.zzuo
248 0.02% 85.75% 53 382057 com.aspose.words.zzYS0.apply
293 0.01% 86.37% 160 382435 com.aspose.words.zzYTE.zzZ8o
355 0.01% 87.06% 1 392938 com.aspose.words.zzYW8.commit
215 0.02% 85.20% 23471 393812 com.aspose.words.zzYXN.zzZfp
332 0.01% 86.82% 12585 382398 com.aspose.words.zzZ09.getDirectRunAttr
120 0.03% 82.82% 100 394482 com.aspose.words.zzZL6.zzZ
286 0.01% 86.28% 2630 364218 com.aspose.words.zzZLE.zzZ
294 0.01% 86.38% 30092 393819 com.aspose.words.zzZY.zzxG

Please review the number of times each method is called for single execution of small document conversion.

Thanks

@avmurthy

We have tested the scenario using the shared code and document (Sampledocumentwithmixedformat.docx). We have not found this issue at our end.

Could you please share the complete steps that you are using to reproduce this issue at our end? We will investigate this issue and provide you more information on it.

It is the same test case i have used internally also. Tested with 2 different documents of different sizes.(Sampledocumentwithmixedformat.docx,190 pages.docx)

The data provided earlier from SAR command output.
I notice the conversion takes about 5-7 seconds with 25+ % of CPU utilization for single execution.
For 190 pages document (which is 300Kb) file it takes around 15-17 seconds with 35+% avg CPU utilization.

Can you please upload your test case results.

@avmurthy

We have tested the scenario using the latest version of Aspose.Words for Java 19.4 at Windows 10 (Core i7) and 8 GB RAM. Here is the result:

It takes around 2 seconds for Sampledocumentwithmixedformat.docx and 10 seconds for 190 pages.docx.

Can you please provide the configuration details?
Also can you share CPU utilization during the test?

This is what i notice when i did internally

java -cp $CLASSPATH:. oracle.apps.okc.unittest.CreateClause

$ sar 1 100

04:54:13 AM CPU %user %nice %system %iowait %steal %idle
04:54:14 AM all 0.81 0.00 0.41 17.65 0.20 80.93
04:54:15 AM all 1.22 0.00 0.20 0.00 0.00 98.58
04:54:16 AM all 0.61 0.00 0.61 3.67 0.20 94.91
04:54:17 AM all 0.61 0.00 0.40 0.81 0.20 97.98
04:54:18 AM all 0.61 0.00 0.20 1.02 0.00 98.17
04:54:19 AM all 0.20 0.00 0.41 0.00 0.20 99.19
04:54:20 AM all 0.41 0.00 0.20 0.00 0.00 99.39
04:54:21 AM all 13.97 0.00 4.25 2.02 0.20 79.55
04:54:22 AM all 33.20 0.00 4.28 0.41 0.20 61.91
04:54:23 AM all 46.86 0.00 3.65 2.43 0.20 46.86
04:54:24 AM all 23.48 0.00 4.25 8.70 0.20 63.36
04:54:25 AM all 28.48 0.00 10.71 6.87 0.20 53.74
04:54:26 AM all 52.93 0.00 2.22 1.21 0.00 43.64
04:54:27 AM all 43.15 0.00 4.44 2.02 0.20 50.20
04:54:28 AM all 45.34 0.00 2.63 0.00 0.20 51.82
04:54:29 AM all 45.66 0.00 5.86 1.01 0.20 47.27
04:54:30 AM all 57.29 0.00 3.64 1.21 0.00 37.85
04:54:31 AM all 57.69 0.00 2.23 4.45 0.20 35.43
04:54:32 AM all 35.56 0.00 5.66 0.00 0.20 58.59
04:54:33 AM all 25.71 0.00 2.02 0.81 0.00 71.46
04:54:34 AM all 10.73 0.00 3.24 1.21 0.20 84.62
04:54:35 AM all 0.20 0.00 0.20 4.66 0.00 94.94
04:54:36 AM all 0.20 0.00 0.00 0.00 0.00 99.80
04:54:37 AM all 0.81 0.00 0.41 10.16 0.20 88.41

@avmurthy

We are working over your query and will get back to you soon.

@avmurthy

Please accept my apologies for late response. Here is the result of test case at our end for Sampledocumentwithmixedformat.docx:

Total RAM 4 GB
Total execution time: 10461 milliseconds
SAR command output:

04:10:08 AM CPU %user %nice %system %iowait %steal %idle
04:10:09 AM all 2.02 0.00 1.01 0.00 0.00 96.97
04:10:10 AM all 2.06 0.00 2.06 0.00 0.00 95.88
04:10:11 AM all 1.00 0.00 3.00 0.00 0.00 96.00
04:10:12 AM all 1.03 0.00 1.03 0.00 0.00 97.94
04:10:13 AM all 1.00 0.00 3.00 0.00 0.00 96.00
04:10:14 AM all 1.03 0.00 1.03 0.00 0.00 97.94
04:10:15 AM all 3.06 0.00 0.00 0.00 0.00 96.94
04:10:16 AM all 3.00 0.00 1.00 0.00 0.00 96.00
04:10:17 AM all 0.00 0.00 2.04 0.00 0.00 97.96
04:10:18 AM all 1.02 0.00 2.04 0.00 0.00 96.94
04:10:19 AM all 2.02 0.00 2.02 0.00 0.00 95.96
04:10:20 AM all 2.04 0.00 1.02 0.00 0.00 96.94
04:10:21 AM all 2.04 0.00 3.06 0.00 0.00 94.90
04:10:22 AM all 1.01 0.00 2.02 0.00 0.00 96.97
04:10:23 AM all 3.03 0.00 0.00 0.00 0.00 96.97
04:10:24 AM all 2.02 0.00 2.02 0.00 0.00 95.96
04:10:25 AM all 2.04 0.00 1.02 0.00 0.00 96.94
04:10:26 AM all 2.04 0.00 1.02 0.00 0.00 96.94
04:10:27 AM all 2.02 0.00 2.02 0.00 0.00 95.96
04:10:28 AM all 3.03 0.00 2.02 0.00 0.00 94.95
04:10:29 AM all 1.01 0.00 2.02 0.00 0.00 96.97
04:10:30 AM all 1.01 0.00 2.02 0.00 0.00 96.97

04:10:30 AM CPU %user %nice %system %iowait %steal %idle
04:10:31 AM all 3.09 0.00 1.03 0.00 0.00 95.88
04:10:32 AM all 3.03 0.00 1.01 0.00 0.00 95.96
04:10:33 AM all 2.00 0.00 2.00 0.00 0.00 96.00
04:10:34 AM all 1.02 0.00 2.04 0.00 0.00 96.94
04:10:35 AM all 1.02 0.00 1.02 0.00 0.00 97.96
04:10:36 AM all 3.03 0.00 1.01 0.00 0.00 95.96
04:10:37 AM all 4.04 0.00 1.01 0.00 0.00 94.95
04:10:38 AM all 29.29 0.00 1.01 0.00 0.00 69.70
Average: all 2.84 0.00 1.56 0.00 0.00 95.60