SCCM packages may be distributed slower than standard file copy (xcopy/Windows Explorer)
Hi there,
In this post, I’m going to mention about another issue where I helped a colleague of mine to troubleshoot an SCCM package distribution scenario. The problem was that package distribution to clients were visibly slower compared to standard file copy methods (like using xcopy, Windows Explorer etc). In the given setup, the sccm client was accessing and retrieving the distribution package via SMB protocol so BITS was out of the picture. We requested the customer to collect the following logs while reproducing the problem:
a) Create a distribution package which simply includes a 100 MB executable file
b) Collect the following logs for two different scenarios:
=> For standard file copy scenario:
- Start Network traces on the SCCM server (Windows 2008 R2) and the SCCM agent (Windows 7)
- Start Process Explorer on the SCCM agent
- Start file copy by using xcopy from a command prompt on Windows 7 client
=> For SCCM package distribution scenario:
- Start Network traces on the SCCM server (Windows 2008 R2) and the SCCM agent (Windows 7)
- Start Process Explorer on the SCCM agent
- Trigger packet distribution
After the above logs collected, I analzyed the network traces and Process monitor logs for both scenarios. Let us take a closer look for each scenario:
A. SCCM PACKAGE DISTRIBUTION SCENARIO
The package download activity was seen as below in Process Monitor:
- Ccmexec posts about 4900 ReadFile()s with 64KB buffers each
- This is also supported by the behavior seen in the network trace collected for ccmexec scenario:
No. Time Source Destination Info Protocol
...
16475 0.005513 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16121856 File: TEST\100MBFile.txt SMB2
16476 0.000013 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16187392 File: TEST\100MBFile.txt SMB2
16478 0.001872 192.168.2.77 192.168.1.7 Read Response SMB2
16538 0.005313 192.168.2.77 192.168.1.7 Read Response SMB2
16603 0.080443 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16252928 File: TEST\100MBFile.txt SMB2
16604 0.000013 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16318464 File: TEST\100MBFile.txt SMB2
16606 0.001229 192.168.2.77 192.168.1.7 Read Response SMB2
16666 0.005312 192.168.2.77 192.168.1.7 Read Response SMB2
16730 0.005827 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16384000 File: TEST\100MBFile.txt SMB2
16731 0.000013 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16449536 File: TEST\100MBFile.txt SMB2
16733 0.001193 192.168.2.77 192.168.1.7 Read Response SMB2
16795 0.005643 192.168.2.77 192.168.1.7 Read Response SMB2
16856 0.070364 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16515072 File: TEST\100MBFile.txt SMB2
16857 0.000013 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16580608 File: TEST\100MBFile.txt SMB2
16859 0.001037 192.168.2.77 192.168.1.7 Read Response SMB2
16919 0.005313 192.168.2.77 192.168.1.7 Read Response SMB2
16982 0.005789 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16646144 File: TEST\100MBFile.txt SMB2
16983 0.000014 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16711680 File: TEST\100MBFile.txt SMB2
16985 0.001043 192.168.2.77 192.168.1.7 Read Response SMB2
17045 0.005312 192.168.2.77 192.168.1.7 Read Response SMB2
17108 0.048421 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16777216 File: TEST\100MBFile.txt SMB2
17109 0.000019 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16842752 File: TEST\100MBFile.txt SMB2
17111 0.002061 192.168.2.77 192.168.1.7 Read Response SMB2
17171 0.005311 192.168.2.77 192.168.1.7 Read Response SMB2
17236 0.055958 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16908288 File: TEST\100MBFile.txt SMB2
17237 0.000015 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:16973824 File: TEST\100MBFile.txt SMB2
17239 0.002242 192.168.2.77 192.168.1.7 Read Response SMB2
17300 0.005311 192.168.2.77 192.168.1.7 Read Response SMB2
...
Note: IP addresses are replaced for privacy purposes
B. STANDARD FILE COPY SCENARIO
The standard file copy with xcopy was seen as below in Process Monitor:
- The xcopy tool posts only 100 ReadFile()s each with a 1 MB buffer each
- This is also seen in the network trace collected for the xcopy scenario:
No. Time Source Destination Info Protocol
...
5445 2010-09-21 15:59:29.436686 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12582912 File: xcopytest\100MBFile.txt SMB2
5446 2010-09-21 15:59:29.436701 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12648448 File: xcopytest\100MBFile.txt SMB2
5447 2010-09-21 15:59:29.436712 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12713984 File: xcopytest\100MBFile.txt SMB2
5448 2010-09-21 15:59:29.436723 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12779520 File: xcopytest\100MBFile.txt SMB2
5449 2010-09-21 15:59:29.436735 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12845056 File: xcopytest\100MBFile.txt SMB2
5450 2010-09-21 15:59:29.436748 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12910592 File: xcopytest\100MBFile.txt SMB2
5451 2010-09-21 15:59:29.436760 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:12976128 File: xcopytest\100MBFile.txt SMB2
5452 2010-09-21 15:59:29.436772 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13041664 File: xcopytest\100MBFile.txt SMB2
5453 2010-09-21 15:59:29.436784 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13107200 File: xcopytest\100MBFile.txt SMB2
5457 2010-09-21 15:59:29.436798 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13172736 File: xcopytest\100MBFile.txt SMB2
5458 2010-09-21 15:59:29.436813 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13238272 File: xcopytest\100MBFile.txt SMB2
5459 2010-09-21 15:59:29.436824 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13303808 File: xcopytest\100MBFile.txt SMB2
5460 2010-09-21 15:59:29.436835 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13369344 File: xcopytest\100MBFile.txt SMB2
5461 2010-09-21 15:59:29.436845 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13434880 File: xcopytest\100MBFile.txt SMB2
5462 2010-09-21 15:59:29.436857 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13500416 File: xcopytest\100MBFile.txt SMB2
5463 2010-09-21 15:59:29.436869 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13565952 File: xcopytest\100MBFile.txt SMB2
5509 2010-09-21 15:59:29.441113 192.168.2.77 192.168.1.7 Read Response SMB2
5572 2010-09-21 15:59:29.446773 192.168.2.77 192.168.1.7 Read Response SMB2
5632 2010-09-21 15:59:29.452104 192.168.2.77 192.168.1.7 [Unreassembled Packet] SMB2
5694 2010-09-21 15:59:29.457766 192.168.2.77 192.168.1.7 Read Response SMB2
5755 2010-09-21 15:59:29.463095 192.168.2.77 192.168.1.7 Read Response SMB2
5817 2010-09-21 15:59:29.468755 192.168.2.77 192.168.1.7 Read Response SMB2
5878 2010-09-21 15:59:29.474076 192.168.2.77 192.168.1.7 Read Response SMB2
5940 2010-09-21 15:59:29.479738 192.168.2.77 192.168.1.7 Read Response SMB2
6002 2010-09-21 15:59:29.485400 192.168.2.77 192.168.1.7 Read Response SMB2
6063 2010-09-21 15:59:29.490729 192.168.2.77 192.168.1.7 Read Response SMB2
6125 2010-09-21 15:59:29.496387 192.168.2.77 192.168.1.7 Read Response SMB2
6187 2010-09-21 15:59:29.502044 192.168.2.77 192.168.1.7 Read Response SMB2
6248 2010-09-21 15:59:29.507367 192.168.2.77 192.168.1.7 Read Response SMB2
6310 2010-09-21 15:59:29.513024 192.168.2.77 192.168.1.7 Read Response SMB2
6372 2010-09-21 15:59:29.518677 192.168.2.77 192.168.1.7 Read Response SMB2
6433 2010-09-21 15:59:29.523999 192.168.2.77 192.168.1.7 Read Response SMB2
6447 2010-09-21 15:59:29.525133 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13631488 File: xcopytest\100MBFile.txt SMB2
6448 2010-09-21 15:59:29.525148 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13697024 File: xcopytest\100MBFile.txt SMB2
6449 2010-09-21 15:59:29.525159 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13762560 File: xcopytest\100MBFile.txt SMB2
6450 2010-09-21 15:59:29.525170 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13828096 File: xcopytest\100MBFile.txt SMB2
6451 2010-09-21 15:59:29.525183 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13893632 File: xcopytest\100MBFile.txt SMB2
6452 2010-09-21 15:59:29.525196 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:13959168 File: xcopytest\100MBFile.txt SMB2
6453 2010-09-21 15:59:29.525207 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14024704 File: xcopytest\100MBFile.txt SMB2
6454 2010-09-21 15:59:29.525219 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14090240 File: xcopytest\100MBFile.txt SMB2
6455 2010-09-21 15:59:29.525231 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14155776 File: xcopytest\100MBFile.txt SMB2
6456 2010-09-21 15:59:29.525243 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14221312 File: xcopytest\100MBFile.txt SMB2
6457 2010-09-21 15:59:29.525255 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14286848 File: xcopytest\100MBFile.txt SMB2
6458 2010-09-21 15:59:29.525267 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14352384 File: xcopytest\100MBFile.txt SMB2
6459 2010-09-21 15:59:29.525280 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14417920 File: xcopytest\100MBFile.txt SMB2
6460 2010-09-21 15:59:29.525292 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14483456 File: xcopytest\100MBFile.txt SMB2
6461 2010-09-21 15:59:29.525304 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14548992 File: xcopytest\100MBFile.txt SMB2
6462 2010-09-21 15:59:29.525316 192.168.1.7 192.168.2.77 Read Request Len:65536 Off:14614528 File: xcopytest\100MBFile.txt SMB2
6511 2010-09-21 15:59:29.529653 192.168.2.77 192.168.1.7 Read Response SMB2
6573 2010-09-21 15:59:29.534977 192.168.2.77 192.168.1.7 Read Response SMB2
6635 2010-09-21 15:59:29.540629 192.168.2.77 192.168.1.7 Read Response SMB2
6697 2010-09-21 15:59:29.546286 192.168.2.77 192.168.1.7 Read Response SMB2
6758 2010-09-21 15:59:29.551606 192.168.2.77 192.168.1.7 [Unreassembled Packet] SMB2
6821 2010-09-21 15:59:29.557255 192.168.2.77 192.168.1.7 Read Response SMB2
6883 2010-09-21 15:59:29.562576 192.168.2.77 192.168.1.7 Read Response SMB2
6945 2010-09-21 15:59:29.568234 192.168.2.77 192.168.1.7 Read Response SMB2
7007 2010-09-21 15:59:29.573893 192.168.2.77 192.168.1.7 Read Response SMB2
7068 2010-09-21 15:59:29.579219 192.168.2.77 192.168.1.7 Read Response SMB2
7130 2010-09-21 15:59:29.584876 192.168.2.77 192.168.1.7 Read Response SMB2
7192 2010-09-21 15:59:29.590530 192.168.2.77 192.168.1.7 Read Response SMB2
7253 2010-09-21 15:59:29.595858 192.168.2.77 192.168.1.7 Read Response SMB2
7315 2010-09-21 15:59:29.601517 192.168.2.77 192.168.1.7 Read Response SMB2
7377 2010-09-21 15:59:29.607173 192.168.2.77 192.168.1.7 Read Response SMB2
7438 2010-09-21 15:59:29.612499 192.168.2.77 192.168.1.7 Read Response SMB2
7500 2010-09-21 15:59:29.618155 192.168.2.77 192.168.1.7 Read Response SMB2
7561 2010-09-21 15:59:29.623478 192.168.2.77 192.168.1.7 Read Response SMB2
7623 2010-09-21 15:59:29.629132 192.168.2.77 192.168.1.7 Read Response SMB2
7685 2010-09-21 15:59:29.634785 192.168.2.77 192.168.1.7 Read Response SMB2
7746 2010-09-21 15:59:29.640111 192.168.2.77 192.168.1.7 Read Response SMB2
7808 2010-09-21 15:59:29.645771 192.168.2.77 192.168.1.7 Read Response SMB2
7871 2010-09-21 15:59:29.651433 192.168.2.77 192.168.1.7 Read Response SMB2
7932 2010-09-21 15:59:29.656750 192.168.2.77 192.168.1.7 Read Response SMB2
7996 2010-09-21 15:59:29.662406 192.168.2.77 192.168.1.7 Read Response SMB2
8058 2010-09-21 15:59:29.667728 192.168.2.77 192.168.1.7 Read Response SMB2
8120 2010-09-21 15:59:29.673385 192.168.2.77 192.168.1.7 Read Response SMB2
8182 2010-09-21 15:59:29.679045 192.168.2.77 192.168.1.7 Read Response SMB2
8243 2010-09-21 15:59:29.684367 192.168.2.77 192.168.1.7 Read Response SMB2
...
Note: IP addresses are replaced for privacy purposes
Note: The above 16 x 64 KB = 1 MB read requests are actually created as a result of 1 MB read requests at the application layer (xcopy)
SUMMARY:
=========
The performance difference between sccm package distribution and xcopy stems from the fact that xcopy tool (and most probably Windows Explorer as well) posts Read requests with larger buffers (1 MB) compared to sccm agent process - ccmexec (64 KB) which results in a better performance in the xcopy scenario since better concurrency is achieved and the network bandwidth is better utilized that way. This is both seen in the network trace and Process Monitor activities. We shared the results with our SCCM colleagues to see if that behaviour could be changed or not, if I receive any update on that I’ll update this post.
Hope this helps
Thanks,
Murat