tracker issue : CF-4206264

select a category, or use search below
(searches all categories and all time range)
Title:

CFFile significantly slower then previously versions

| View in Tracker

Status/Resolution/Reason: Closed/Withdrawn/CannotReproduce

Reporter/Name(from Bugbase): Toby W. / ()

Created: 12/05/2019

Components: File Management, CFFile, Performance

Versions: 2018

Failure Type: Non Functioning

Found In Build/Fixed In Build: CF2018 /

Priority/Frequency: Normal / All users will encounter

Locale/System: English / Win 2012 Server x64

Vote Count: 1

Problem Description:

cffile action = "copy" is about 3-4 times slower in CF 2018 compared to CF 11.

Processing images using the cffile tag is much slower on CF 2018 then CF 11. Doing a simple copy take a lot longer. Add that to processing multiple images and the time can increase significantly.

I have tested this with the same spec machines, fresh installed & upgrade. Both win 2012 and 2016 OS. 

Configurations for CF are the same.

CF 11 -  11,0,18,314030 , Java 1.8.0_171   

CF 2018 - 2018,0,06,316308, Java 11.0.1  



Steps to Reproduce:

Repro attached to bug.

Run something like:

<cffile action = "copy" source = "C:/Temp/testimg1.JPG" destination = "C:/Temp/testimg2.JPG">

on CF 11 then repeat on CF 2018


Actual Result:

Process taking 3-4 times longer


Expected Result:

Similar run times to CF 11


Any Workarounds:

None

Revert to CF 11 or use third party tools

Attachments:

Comments:

Here are some timings for the testing I have done using the repro attached This is made substantially worse when using S3:// which is where we are noticing the difference CF11 Local Test 1: 0ms Test 2: 0ms Test 3: 1ms S3 Test 1: 328ms Test 2: 578ms Test 3: 391ms CF 2018 Local Test 1: 4ms Test 2: 5ms Test 3: 4ms S3 Test 1: 803ms Test 2: 1290ms Test 3: 968ms
Comment by Toby W.
31929 | December 05, 2019 09:12:52 AM GMT
ALTERNATIVE: If you are copying/syncing static resources to S3, you may want to consider using CFExecute with S3Express (portable CLI/command line). https://www.s3express.com/ I've found it to be a better alternative, supports multiple threads (faster), gets updated more often & supports newer S3 features, their dev team is responsive and you can auto-generate a log of what transactions were performed. We generate a BAT file, use CFExecute with an immediate timeout and then check the file system for a log at the end of the transaction. This prevents us from locking a thread or consuming RAM dedicated to Java. Here's a sample command line. (The S3Express website has many more samples.) https://gist.github.com/JamoCA/727120f97b33fed5528a We've used S3Express for syncing digital assets for commercial sale (using time-limited download link), backing up SQL and syncing JS/CSS resources to our CDN. (We initially desired to use the built-in S3 support, but found it to be slow, unreliable and didn't support latest S3 features.)
Comment by James M.
31930 | December 06, 2019 02:56:55 PM GMT
Toby, with a local disk based 25KB file, copying w/ CF11 and CF2018, takes about the same time on my test machine (2ms) - is your CF11 and CF2018 on the same host platform? - what is the update level you are on on CF2018? - what is the size of the file you're copying?
Comment by Piyush K.
32029 | January 08, 2020 07:19:34 AM GMT
Update levels are shown above in the first post. All servers are running on the same platform. Dedicated storage. The same issue is replicated on my local test servers internally as well. So storage devices are rules out The file size was approx 50kb This issue is more to do with S3 then local. We can deal with 2-4ms but S3 is terrible
Comment by Toby W.
32030 | January 08, 2020 07:43:26 AM GMT
Worth noting that I am now running HF 7. I have also tested with different versions of Java incase the issue is there but the results are the same
Comment by Toby W.
32031 | January 08, 2020 07:44:27 AM GMT
Toby, I still don't see the issue when copying files from s3 to s3. I'm sharing the test code that I used and the results below: Can you double check if you have anything in your Application cfc or onRequestStart/Stop methods that could have a bearing on your numbers. time elapsed in ms w/ the respective CF version: 2018.0.07.316715 trusted caching disabled, all files: 12513, 12953, 13833 trusted caching enabled, all files: 11007, 12104, 12623, 11339 trusted caching enabled, just the jpg file: 4393, 4744, 4324, 5092 11,0,19,314262 trusted caching disabled, all files: 17275, 15252, 19136 trusted caching enabled: 12826, 12428, 12436 trusted caching enabled, just the jpg: 4651, 4470 test script: <cfset srcDir = "s3://cfqa.srcdirperf"> <cfif !directoryExists("#srcDir#")> <cfset directoryCreate(srcDir)> </cfif> created dir: <cfoutput>#srcDir#</cfoutput><br> copying files from local disk to cloud...<br> <!--- <cffile action="write" file="#srcDir#/docs/Sample.txt" output="This is txt file in s3"> <cffile action="copy" source="#ExpandPath('./docs/Colors.jpg')#" destination="#srcDir#/docs/Sample.jpg"> <cffile action="copy" source="#ExpandPath('./docs/s3-notes.pdf')#" destination="#srcDir#/docs/Sample.pdf"> <cffile action="copy" source="#ExpandPath('./docs/Sample.mp3')#" destination="#srcDir#/docs/Sample.mp3"> ----> <cfdirectory action = "list" directory = "#srcDir#" name="listFl"> <cfdump var=#listFl# label="copied src files..."> <cfset destDir = "s3://cfqa.desrdirperf"> <cfif !directoryExists(destDir)> <cfset directoryCreate(destDir)> </cfif> created dir: <cfoutput>#destDir#</cfoutput><br> copying files from cloud dir1 to cloud dir2...<br> <cfset t0 = getTickCount()> <cfloop from=1 to="#listFl.recordCount()#" index="r"> <cfset srcFile = "#listFl["Directory"][r]##listFl["name"][r]#" > <cfset destFile = "#destDir#/#listFl["name"][r]#"> <cfoutput>copying #srcFile# to #destDir#</cfoutput>....<br> <cffile action="copy" source="#srcFile#" destination="#destDir#"> </cfloop> elasped time: <cfoutput>#(getTickCount() - t0)#</cfoutput><br> <cfdirectory action = "list" directory = "#destDir#" name="listFl"> <cfdump var=#listFl# label="copied src files..."> <cfif directoryExists("#destDir#") > <cfdirectory action="delete" directory="#destDir#" recurse="true" > </cfif> Attributes DateLastModified Directory Link Mode Name Size Type 1 [empty string] 03/02/2020 02:30:00 PM s3://cfqa.srcdirperf/ NO [empty string] docs/Sample.jpg 2138 File 2 [empty string] 03/02/2020 02:30:05 PM s3://cfqa.srcdirperf/ NO [empty string] docs/Sample.mp3 2925759 File 3 [empty string] 03/02/2020 02:30:03 PM s3://cfqa.srcdirperf/ NO [empty string] docs/Sample.pdf 35161 File 4 [empty string] 03/02/2020 02:29:59 PM s3://cfqa.srcdirperf/ NO [empty string] docs/Sample.txt 24 File
Comment by Piyush K.
33217 | March 02, 2020 11:21:11 AM GMT
We dont copy s3 to s3, only local to s3. Can you do the test at the basic level and just copy local to local. Even though it is still a low time to transfer, its still 3-4 times worse (as per my results above) What size file are you using? Could you use something around 2MB?
Comment by Toby W.
33227 | March 02, 2020 12:01:00 PM GMT
Toby, The mp3 file in the stats that I shared earlier is close to 3Mb. The test case you've shared copies from local to local and cloud to cloud, not local to s3. did you check to see if you have anything in Application.cfc that could affect your stats. how about the caching settings on both your CFs. You may want to get in touch with the support team if you need help with isolating any set-up related factors affecting the performance. I did share in my first note that copying from local to local with 25kb file takes about the same time with CF11 and CF2018. Anyway I've tried that again with a ~3Mb file . Here are the nos. with a loop for demonstrative purposes ... I don't see the difference even if I run the code without the loop construct. <cfloop from=1 to=10 index="n"> <cfset t0 = getTickCount()> <cffile action="copy" source="#srcDir#/Sample.mp3" destination="#destDir#/Sample#n#.mp3"> elasped time: <cfoutput>#(getTickCount() - t0)#</cfoutput><br> </cfloop> CF2018u7: elasped time: 6 elasped time: 4 elasped time: 4 elasped time: 3 elasped time: 3 elasped time: 3 elasped time: 4 elasped time: 4 elasped time: 4 elasped time: 3 CF11u19: elasped time: 5 elasped time: 4 elasped time: 4 elasped time: 4 elasped time: 4 elasped time: 3 elasped time: 3 elasped time: 3 elasped time: 3 elasped time: 7
Comment by Piyush K.
33264 | March 06, 2020 08:00:47 AM GMT
closing as not reproducible, this since I don't see the difference with my tests.
Comment by Piyush K.
33296 | March 16, 2020 07:36:54 AM GMT