[ https://issues.apache.org/jira/browse/SPARK-3570?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14318960#comment-14318960 ]
Kay Ousterhout commented on SPARK-3570: --------------------------------------- There are a bunch of times when files are opened and written to that are not currently logged, so I did some investigation of this to figure out when the time may be significant and is therefore worth logging. I did this on a 5-machine cluster using ext3 (which exacerbates disk access issues, making it easy to see when times may be long) running query 3a of the big data benchmark (which struggles with disk access because of the many shuffle files). Here's what I found: SortShuffleWriter.write, call to shuffleBlockManager.getDataFile: this just opens 1 file, and typically takes about 100us, so not worth adding logging SortShuffleWriter.write, call to shuffleBlockManager.getIndexFile: this writes a single index file and typically took about 0.1ms (as high as 1ms). Also doesn't seem worth logging. ExternalSorter.spillToPartitionFiles, creating the disk writers for each partition: because this creates one file for each partition, the time to create all of the files adds up: this took 75-100ms ExternalSorter.writePartitionedFile, copying the data from the partitioned files to a single file: because this reads and writes all of the shuffle data, it can be long; ~13ms on the workload I looked at. ExternalSorter.writePartitionedFile, time to call blockManager.getDiskWriter on line 748: getDiskWriter *CAN* take a long time because of the call to file.length(), which may hit disk. However, in this case, each call takes 20us or less (and this is likely noisy -- getting small to measure). To totally speculate, I'd guess that because this is called many times on the same file, as opposed to different files, and the file is actively being written to, the length is cached in memory by the OS. To summarize, this all leads to the intuitive conclusion that we only need to long when we're writing lots of data (e.g., when copying all of the shuffle data to a single file) or when we're opening a lot of files. > Shuffle write time does not include time to open shuffle files > -------------------------------------------------------------- > > Key: SPARK-3570 > URL: https://issues.apache.org/jira/browse/SPARK-3570 > Project: Spark > Issue Type: Bug > Components: Spark Core > Affects Versions: 0.9.2, 1.0.2, 1.1.0 > Reporter: Kay Ousterhout > Assignee: Kay Ousterhout > Attachments: 3a_1410854905_0_job_log_waterfall.pdf, > 3a_1410957857_0_job_log_waterfall.pdf > > > Currently, the reported shuffle write time does not include time to open the > shuffle files. This time can be very significant when the disk is highly > utilized and many shuffle files exist on the machine (I'm not sure how severe > this is in 1.0 onward -- since shuffle files are automatically deleted, this > may be less of an issue because there are fewer old files sitting around). > In experiments I did, in extreme cases, adding the time to open files can > increase the shuffle write time from 5ms (of a 2 second task) to 1 second. > We should fix this for better performance debugging. > Thanks [~shivaram] for helping to diagnose this problem. cc [~pwendell] -- This message was sent by Atlassian JIRA (v6.3.4#6332) --------------------------------------------------------------------- To unsubscribe, e-mail: issues-unsubscr...@spark.apache.org For additional commands, e-mail: issues-h...@spark.apache.org