You are viewing a plain text version of this content. The canonical link for it is here.
Posted to mapreduce-user@hadoop.apache.org by Robert Schmidtke <ro...@gmail.com> on 2015/11/27 17:07:36 UTC
HDFS TestDFSIO performance with 1 mapper/file of 16G per node
Hi everyone,
I cannot seem to wrap my head around the TestDFSIO benchmark results. I
have a cluster of 8 nodes, the first one runs the NameNode and the
ResourceManager, the others each run a DataNode and a NodeManager. Each
node has 64G of RAM. I am using a block size for HDFS of 128M, and a
replication factor of 3. I'm running the benchmark with 7 map tasks, each
processing one file of 16G. The results are as follows:
For the write phase:
15/11/27 14:50:32 INFO mapreduce.Job: Counters: 49
File System Counters
FILE: Number of bytes read=626
FILE: Number of bytes written=929305
FILE: Number of read operations=0
FILE: Number of large read operations=0
FILE: Number of write operations=0
HDFS: Number of bytes read=1673
HDFS: Number of bytes written=120259084369
HDFS: Number of read operations=31
HDFS: Number of large read operations=0
HDFS: Number of write operations=9
Job Counters
Launched map tasks=7
Launched reduce tasks=1
Data-local map tasks=7
Total time spent by all maps in occupied slots (ms)=3816135
Total time spent by all reduces in occupied slots (ms)=277826
Total time spent by all map tasks (ms)=3816135
Total time spent by all reduce tasks (ms)=277826
Total vcore-seconds taken by all map tasks=3816135
Total vcore-seconds taken by all reduce tasks=277826
Total megabyte-seconds taken by all map tasks=3907722240
Total megabyte-seconds taken by all reduce tasks=284493824
Map-Reduce Framework
Map input records=7
Map output records=35
Map output bytes=550
Map output materialized bytes=662
Input split bytes=889
Combine input records=0
Combine output records=0
Reduce input groups=5
Reduce shuffle bytes=662
Reduce input records=35
Reduce output records=5
Spilled Records=70
Shuffled Maps =7
Failed Shuffles=0
Merged Map outputs=7
GC time elapsed (ms)=73040
CPU time spent (ms)=754470
Physical memory (bytes) snapshot=2070585344
Virtual memory (bytes) snapshot=7448678400
Total committed heap usage (bytes)=1346895872
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=784
File Output Format Counters
Bytes Written=81
15/11/27 14:50:32 INFO fs.TestDFSIO: ----- TestDFSIO ----- : write
15/11/27 14:50:32 INFO fs.TestDFSIO: Date & time: Fri Nov 27
14:50:32 CET 2015
15/11/27 14:50:32 INFO fs.TestDFSIO: Number of files: 7
15/11/27 14:50:32 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
15/11/27 14:50:32 INFO fs.TestDFSIO: Throughput mb/sec:
30.260630125485257
15/11/27 14:50:32 INFO fs.TestDFSIO: Average IO rate mb/sec:
31.812650680541992
15/11/27 14:50:32 INFO fs.TestDFSIO: IO rate std deviation:
6.862839589024802
15/11/27 14:50:32 INFO fs.TestDFSIO: Test exec time sec: 705.559
For the read phase:
15/11/27 14:56:46 INFO mapreduce.Job: Counters: 51
File System Counters
FILE: Number of bytes read=637
FILE: Number of bytes written=929311
FILE: Number of read operations=0
FILE: Number of large read operations=0
FILE: Number of write operations=0
HDFS: Number of bytes read=120259085961
HDFS: Number of bytes written=84
HDFS: Number of read operations=38
HDFS: Number of large read operations=0
HDFS: Number of write operations=2
Job Counters
Killed map tasks=4
Launched map tasks=11
Launched reduce tasks=1
Data-local map tasks=9
Rack-local map tasks=2
Total time spent by all maps in occupied slots (ms)=2096182
Total time spent by all reduces in occupied slots (ms)=272737
Total time spent by all map tasks (ms)=2096182
Total time spent by all reduce tasks (ms)=272737
Total vcore-seconds taken by all map tasks=2096182
Total vcore-seconds taken by all reduce tasks=272737
Total megabyte-seconds taken by all map tasks=2146490368
Total megabyte-seconds taken by all reduce tasks=279282688
Map-Reduce Framework
Map input records=7
Map output records=35
Map output bytes=561
Map output materialized bytes=673
Input split bytes=889
Combine input records=0
Combine output records=0
Reduce input groups=5
Reduce shuffle bytes=673
Reduce input records=35
Reduce output records=5
Spilled Records=70
Shuffled Maps =7
Failed Shuffles=0
Merged Map outputs=7
GC time elapsed (ms)=1407
CPU time spent (ms)=96580
Physical memory (bytes) snapshot=1945346048
Virtual memory (bytes) snapshot=7420182528
Total committed heap usage (bytes)=1421869056
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=784
File Output Format Counters
Bytes Written=84
15/11/27 14:56:46 INFO fs.TestDFSIO: ----- TestDFSIO ----- : read
15/11/27 14:56:46 INFO fs.TestDFSIO: Date & time: Fri Nov 27
14:56:46 CET 2015
15/11/27 14:56:46 INFO fs.TestDFSIO: Number of files: 7
15/11/27 14:56:46 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
15/11/27 14:56:46 INFO fs.TestDFSIO: Throughput mb/sec:
101.66069077999725
15/11/27 14:56:46 INFO fs.TestDFSIO: Average IO rate mb/sec: 153.29443359375
15/11/27 14:56:46 INFO fs.TestDFSIO: IO rate std deviation:
115.23795112362669
15/11/27 14:56:46 INFO fs.TestDFSIO: Test exec time sec: 370.396
I usually average over a number of runs, but this is just a single one. I
have seen much greater execution times for both the write and the read
phases (up to 2x the ones stated above). I have compared the performance to
XtreemFS, another distributed file system, and it achieves an average write
rate that is around 6x faster, and an average read rate that is around 2.5x
faster, however with a much lower standard deviation rate. Note that HDFS
outperforms XtreemFS in terms of TestDFSIO benchmark results with smaller
files (1G). I also don' understand why map tasks are being killed.
I noticed that quite some time is spent on GC, so I plotted some system
metrics for one node running a DataNode/NodeManager (the write phase stops
and the read phase starts at around 14:51):
I am wondering why the system RAM usage goes all the way up to the Yarn
container limit of around 60G, when only one 16G file is being written
to/read from on this node.
So, to sum up a list of questions that I would like to ask your advice
about:
- Has anyone observed similar behavior/performance with HDFS and large
files?
- Which configuration parameters would I need to tweak in order to increase
performance, or which system properties do I need to examine for you to
give me helpful advice here?
- Why is the RAM consumption so high?
- Why is the reported standard deviation during read phases so high?
Thanks in advance for your time and effort!
Robert
--
My GPG Key ID: 336E2680
Re: HDFS TestDFSIO performance with 1 mapper/file of 16G per node
Posted by Andreas Fritzler <an...@gmail.com>.
Hi Robert,
I'm experiencing the same effect regarding the RAM consumption when running
TestDFSIO with huge files. I cound't really find out yet why this is
happening though.
One question regarding your setup: Are you running your cluster on bare
metal or virtualized?
Regards,
Andreas
On Fri, Nov 27, 2015 at 5:07 PM, Robert Schmidtke <ro...@gmail.com>
wrote:
> Hi everyone,
>
> I cannot seem to wrap my head around the TestDFSIO benchmark results. I
> have a cluster of 8 nodes, the first one runs the NameNode and the
> ResourceManager, the others each run a DataNode and a NodeManager. Each
> node has 64G of RAM. I am using a block size for HDFS of 128M, and a
> replication factor of 3. I'm running the benchmark with 7 map tasks, each
> processing one file of 16G. The results are as follows:
>
> For the write phase:
> 15/11/27 14:50:32 INFO mapreduce.Job: Counters: 49
> File System Counters
> FILE: Number of bytes read=626
> FILE: Number of bytes written=929305
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=1673
> HDFS: Number of bytes written=120259084369
> HDFS: Number of read operations=31
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=9
> Job Counters
> Launched map tasks=7
> Launched reduce tasks=1
> Data-local map tasks=7
> Total time spent by all maps in occupied slots (ms)=3816135
> Total time spent by all reduces in occupied slots (ms)=277826
> Total time spent by all map tasks (ms)=3816135
> Total time spent by all reduce tasks (ms)=277826
> Total vcore-seconds taken by all map tasks=3816135
> Total vcore-seconds taken by all reduce tasks=277826
> Total megabyte-seconds taken by all map tasks=3907722240
> Total megabyte-seconds taken by all reduce tasks=284493824
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=550
> Map output materialized bytes=662
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=662
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=73040
> CPU time spent (ms)=754470
> Physical memory (bytes) snapshot=2070585344
> Virtual memory (bytes) snapshot=7448678400
> Total committed heap usage (bytes)=1346895872
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=81
> 15/11/27 14:50:32 INFO fs.TestDFSIO: ----- TestDFSIO ----- : write
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:50:32 CET 2015
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Throughput mb/sec:
> 30.260630125485257
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 31.812650680541992
> 15/11/27 14:50:32 INFO fs.TestDFSIO: IO rate std deviation:
> 6.862839589024802
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Test exec time sec: 705.559
>
> For the read phase:
> 15/11/27 14:56:46 INFO mapreduce.Job: Counters: 51
> File System Counters
> FILE: Number of bytes read=637
> FILE: Number of bytes written=929311
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=120259085961
> HDFS: Number of bytes written=84
> HDFS: Number of read operations=38
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=2
> Job Counters
> Killed map tasks=4
> Launched map tasks=11
> Launched reduce tasks=1
> Data-local map tasks=9
> Rack-local map tasks=2
> Total time spent by all maps in occupied slots (ms)=2096182
> Total time spent by all reduces in occupied slots (ms)=272737
> Total time spent by all map tasks (ms)=2096182
> Total time spent by all reduce tasks (ms)=272737
> Total vcore-seconds taken by all map tasks=2096182
> Total vcore-seconds taken by all reduce tasks=272737
> Total megabyte-seconds taken by all map tasks=2146490368
> Total megabyte-seconds taken by all reduce tasks=279282688
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=561
> Map output materialized bytes=673
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=673
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=1407
> CPU time spent (ms)=96580
> Physical memory (bytes) snapshot=1945346048
> Virtual memory (bytes) snapshot=7420182528
> Total committed heap usage (bytes)=1421869056
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=84
> 15/11/27 14:56:46 INFO fs.TestDFSIO: ----- TestDFSIO ----- : read
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:56:46 CET 2015
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Throughput mb/sec:
> 101.66069077999725
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 153.29443359375
> 15/11/27 14:56:46 INFO fs.TestDFSIO: IO rate std deviation:
> 115.23795112362669
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Test exec time sec: 370.396
>
> I usually average over a number of runs, but this is just a single one. I
> have seen much greater execution times for both the write and the read
> phases (up to 2x the ones stated above). I have compared the performance to
> XtreemFS, another distributed file system, and it achieves an average write
> rate that is around 6x faster, and an average read rate that is around 2.5x
> faster, however with a much lower standard deviation rate. Note that HDFS
> outperforms XtreemFS in terms of TestDFSIO benchmark results with smaller
> files (1G). I also don' understand why map tasks are being killed.
>
> I noticed that quite some time is spent on GC, so I plotted some system
> metrics for one node running a DataNode/NodeManager (the write phase stops
> and the read phase starts at around 14:51):
>
>
>
> I am wondering why the system RAM usage goes all the way up to the Yarn
> container limit of around 60G, when only one 16G file is being written
> to/read from on this node.
>
> So, to sum up a list of questions that I would like to ask your advice
> about:
>
> - Has anyone observed similar behavior/performance with HDFS and large
> files?
> - Which configuration parameters would I need to tweak in order to
> increase performance, or which system properties do I need to examine for
> you to give me helpful advice here?
> - Why is the RAM consumption so high?
> - Why is the reported standard deviation during read phases so high?
>
> Thanks in advance for your time and effort!
>
> Robert
>
> --
> My GPG Key ID: 336E2680
>
Re: HDFS TestDFSIO performance with 1 mapper/file of 16G per node
Posted by Andreas Fritzler <an...@gmail.com>.
Hi Robert,
I'm experiencing the same effect regarding the RAM consumption when running
TestDFSIO with huge files. I cound't really find out yet why this is
happening though.
One question regarding your setup: Are you running your cluster on bare
metal or virtualized?
Regards,
Andreas
On Fri, Nov 27, 2015 at 5:07 PM, Robert Schmidtke <ro...@gmail.com>
wrote:
> Hi everyone,
>
> I cannot seem to wrap my head around the TestDFSIO benchmark results. I
> have a cluster of 8 nodes, the first one runs the NameNode and the
> ResourceManager, the others each run a DataNode and a NodeManager. Each
> node has 64G of RAM. I am using a block size for HDFS of 128M, and a
> replication factor of 3. I'm running the benchmark with 7 map tasks, each
> processing one file of 16G. The results are as follows:
>
> For the write phase:
> 15/11/27 14:50:32 INFO mapreduce.Job: Counters: 49
> File System Counters
> FILE: Number of bytes read=626
> FILE: Number of bytes written=929305
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=1673
> HDFS: Number of bytes written=120259084369
> HDFS: Number of read operations=31
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=9
> Job Counters
> Launched map tasks=7
> Launched reduce tasks=1
> Data-local map tasks=7
> Total time spent by all maps in occupied slots (ms)=3816135
> Total time spent by all reduces in occupied slots (ms)=277826
> Total time spent by all map tasks (ms)=3816135
> Total time spent by all reduce tasks (ms)=277826
> Total vcore-seconds taken by all map tasks=3816135
> Total vcore-seconds taken by all reduce tasks=277826
> Total megabyte-seconds taken by all map tasks=3907722240
> Total megabyte-seconds taken by all reduce tasks=284493824
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=550
> Map output materialized bytes=662
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=662
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=73040
> CPU time spent (ms)=754470
> Physical memory (bytes) snapshot=2070585344
> Virtual memory (bytes) snapshot=7448678400
> Total committed heap usage (bytes)=1346895872
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=81
> 15/11/27 14:50:32 INFO fs.TestDFSIO: ----- TestDFSIO ----- : write
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:50:32 CET 2015
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Throughput mb/sec:
> 30.260630125485257
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 31.812650680541992
> 15/11/27 14:50:32 INFO fs.TestDFSIO: IO rate std deviation:
> 6.862839589024802
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Test exec time sec: 705.559
>
> For the read phase:
> 15/11/27 14:56:46 INFO mapreduce.Job: Counters: 51
> File System Counters
> FILE: Number of bytes read=637
> FILE: Number of bytes written=929311
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=120259085961
> HDFS: Number of bytes written=84
> HDFS: Number of read operations=38
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=2
> Job Counters
> Killed map tasks=4
> Launched map tasks=11
> Launched reduce tasks=1
> Data-local map tasks=9
> Rack-local map tasks=2
> Total time spent by all maps in occupied slots (ms)=2096182
> Total time spent by all reduces in occupied slots (ms)=272737
> Total time spent by all map tasks (ms)=2096182
> Total time spent by all reduce tasks (ms)=272737
> Total vcore-seconds taken by all map tasks=2096182
> Total vcore-seconds taken by all reduce tasks=272737
> Total megabyte-seconds taken by all map tasks=2146490368
> Total megabyte-seconds taken by all reduce tasks=279282688
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=561
> Map output materialized bytes=673
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=673
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=1407
> CPU time spent (ms)=96580
> Physical memory (bytes) snapshot=1945346048
> Virtual memory (bytes) snapshot=7420182528
> Total committed heap usage (bytes)=1421869056
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=84
> 15/11/27 14:56:46 INFO fs.TestDFSIO: ----- TestDFSIO ----- : read
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:56:46 CET 2015
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Throughput mb/sec:
> 101.66069077999725
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 153.29443359375
> 15/11/27 14:56:46 INFO fs.TestDFSIO: IO rate std deviation:
> 115.23795112362669
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Test exec time sec: 370.396
>
> I usually average over a number of runs, but this is just a single one. I
> have seen much greater execution times for both the write and the read
> phases (up to 2x the ones stated above). I have compared the performance to
> XtreemFS, another distributed file system, and it achieves an average write
> rate that is around 6x faster, and an average read rate that is around 2.5x
> faster, however with a much lower standard deviation rate. Note that HDFS
> outperforms XtreemFS in terms of TestDFSIO benchmark results with smaller
> files (1G). I also don' understand why map tasks are being killed.
>
> I noticed that quite some time is spent on GC, so I plotted some system
> metrics for one node running a DataNode/NodeManager (the write phase stops
> and the read phase starts at around 14:51):
>
>
>
> I am wondering why the system RAM usage goes all the way up to the Yarn
> container limit of around 60G, when only one 16G file is being written
> to/read from on this node.
>
> So, to sum up a list of questions that I would like to ask your advice
> about:
>
> - Has anyone observed similar behavior/performance with HDFS and large
> files?
> - Which configuration parameters would I need to tweak in order to
> increase performance, or which system properties do I need to examine for
> you to give me helpful advice here?
> - Why is the RAM consumption so high?
> - Why is the reported standard deviation during read phases so high?
>
> Thanks in advance for your time and effort!
>
> Robert
>
> --
> My GPG Key ID: 336E2680
>
Re: HDFS TestDFSIO performance with 1 mapper/file of 16G per node
Posted by Andreas Fritzler <an...@gmail.com>.
Hi Robert,
I'm experiencing the same effect regarding the RAM consumption when running
TestDFSIO with huge files. I cound't really find out yet why this is
happening though.
One question regarding your setup: Are you running your cluster on bare
metal or virtualized?
Regards,
Andreas
On Fri, Nov 27, 2015 at 5:07 PM, Robert Schmidtke <ro...@gmail.com>
wrote:
> Hi everyone,
>
> I cannot seem to wrap my head around the TestDFSIO benchmark results. I
> have a cluster of 8 nodes, the first one runs the NameNode and the
> ResourceManager, the others each run a DataNode and a NodeManager. Each
> node has 64G of RAM. I am using a block size for HDFS of 128M, and a
> replication factor of 3. I'm running the benchmark with 7 map tasks, each
> processing one file of 16G. The results are as follows:
>
> For the write phase:
> 15/11/27 14:50:32 INFO mapreduce.Job: Counters: 49
> File System Counters
> FILE: Number of bytes read=626
> FILE: Number of bytes written=929305
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=1673
> HDFS: Number of bytes written=120259084369
> HDFS: Number of read operations=31
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=9
> Job Counters
> Launched map tasks=7
> Launched reduce tasks=1
> Data-local map tasks=7
> Total time spent by all maps in occupied slots (ms)=3816135
> Total time spent by all reduces in occupied slots (ms)=277826
> Total time spent by all map tasks (ms)=3816135
> Total time spent by all reduce tasks (ms)=277826
> Total vcore-seconds taken by all map tasks=3816135
> Total vcore-seconds taken by all reduce tasks=277826
> Total megabyte-seconds taken by all map tasks=3907722240
> Total megabyte-seconds taken by all reduce tasks=284493824
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=550
> Map output materialized bytes=662
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=662
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=73040
> CPU time spent (ms)=754470
> Physical memory (bytes) snapshot=2070585344
> Virtual memory (bytes) snapshot=7448678400
> Total committed heap usage (bytes)=1346895872
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=81
> 15/11/27 14:50:32 INFO fs.TestDFSIO: ----- TestDFSIO ----- : write
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:50:32 CET 2015
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Throughput mb/sec:
> 30.260630125485257
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 31.812650680541992
> 15/11/27 14:50:32 INFO fs.TestDFSIO: IO rate std deviation:
> 6.862839589024802
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Test exec time sec: 705.559
>
> For the read phase:
> 15/11/27 14:56:46 INFO mapreduce.Job: Counters: 51
> File System Counters
> FILE: Number of bytes read=637
> FILE: Number of bytes written=929311
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=120259085961
> HDFS: Number of bytes written=84
> HDFS: Number of read operations=38
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=2
> Job Counters
> Killed map tasks=4
> Launched map tasks=11
> Launched reduce tasks=1
> Data-local map tasks=9
> Rack-local map tasks=2
> Total time spent by all maps in occupied slots (ms)=2096182
> Total time spent by all reduces in occupied slots (ms)=272737
> Total time spent by all map tasks (ms)=2096182
> Total time spent by all reduce tasks (ms)=272737
> Total vcore-seconds taken by all map tasks=2096182
> Total vcore-seconds taken by all reduce tasks=272737
> Total megabyte-seconds taken by all map tasks=2146490368
> Total megabyte-seconds taken by all reduce tasks=279282688
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=561
> Map output materialized bytes=673
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=673
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=1407
> CPU time spent (ms)=96580
> Physical memory (bytes) snapshot=1945346048
> Virtual memory (bytes) snapshot=7420182528
> Total committed heap usage (bytes)=1421869056
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=84
> 15/11/27 14:56:46 INFO fs.TestDFSIO: ----- TestDFSIO ----- : read
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:56:46 CET 2015
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Throughput mb/sec:
> 101.66069077999725
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 153.29443359375
> 15/11/27 14:56:46 INFO fs.TestDFSIO: IO rate std deviation:
> 115.23795112362669
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Test exec time sec: 370.396
>
> I usually average over a number of runs, but this is just a single one. I
> have seen much greater execution times for both the write and the read
> phases (up to 2x the ones stated above). I have compared the performance to
> XtreemFS, another distributed file system, and it achieves an average write
> rate that is around 6x faster, and an average read rate that is around 2.5x
> faster, however with a much lower standard deviation rate. Note that HDFS
> outperforms XtreemFS in terms of TestDFSIO benchmark results with smaller
> files (1G). I also don' understand why map tasks are being killed.
>
> I noticed that quite some time is spent on GC, so I plotted some system
> metrics for one node running a DataNode/NodeManager (the write phase stops
> and the read phase starts at around 14:51):
>
>
>
> I am wondering why the system RAM usage goes all the way up to the Yarn
> container limit of around 60G, when only one 16G file is being written
> to/read from on this node.
>
> So, to sum up a list of questions that I would like to ask your advice
> about:
>
> - Has anyone observed similar behavior/performance with HDFS and large
> files?
> - Which configuration parameters would I need to tweak in order to
> increase performance, or which system properties do I need to examine for
> you to give me helpful advice here?
> - Why is the RAM consumption so high?
> - Why is the reported standard deviation during read phases so high?
>
> Thanks in advance for your time and effort!
>
> Robert
>
> --
> My GPG Key ID: 336E2680
>
Re: HDFS TestDFSIO performance with 1 mapper/file of 16G per node
Posted by Andreas Fritzler <an...@gmail.com>.
Hi Robert,
I'm experiencing the same effect regarding the RAM consumption when running
TestDFSIO with huge files. I cound't really find out yet why this is
happening though.
One question regarding your setup: Are you running your cluster on bare
metal or virtualized?
Regards,
Andreas
On Fri, Nov 27, 2015 at 5:07 PM, Robert Schmidtke <ro...@gmail.com>
wrote:
> Hi everyone,
>
> I cannot seem to wrap my head around the TestDFSIO benchmark results. I
> have a cluster of 8 nodes, the first one runs the NameNode and the
> ResourceManager, the others each run a DataNode and a NodeManager. Each
> node has 64G of RAM. I am using a block size for HDFS of 128M, and a
> replication factor of 3. I'm running the benchmark with 7 map tasks, each
> processing one file of 16G. The results are as follows:
>
> For the write phase:
> 15/11/27 14:50:32 INFO mapreduce.Job: Counters: 49
> File System Counters
> FILE: Number of bytes read=626
> FILE: Number of bytes written=929305
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=1673
> HDFS: Number of bytes written=120259084369
> HDFS: Number of read operations=31
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=9
> Job Counters
> Launched map tasks=7
> Launched reduce tasks=1
> Data-local map tasks=7
> Total time spent by all maps in occupied slots (ms)=3816135
> Total time spent by all reduces in occupied slots (ms)=277826
> Total time spent by all map tasks (ms)=3816135
> Total time spent by all reduce tasks (ms)=277826
> Total vcore-seconds taken by all map tasks=3816135
> Total vcore-seconds taken by all reduce tasks=277826
> Total megabyte-seconds taken by all map tasks=3907722240
> Total megabyte-seconds taken by all reduce tasks=284493824
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=550
> Map output materialized bytes=662
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=662
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=73040
> CPU time spent (ms)=754470
> Physical memory (bytes) snapshot=2070585344
> Virtual memory (bytes) snapshot=7448678400
> Total committed heap usage (bytes)=1346895872
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=81
> 15/11/27 14:50:32 INFO fs.TestDFSIO: ----- TestDFSIO ----- : write
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:50:32 CET 2015
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Throughput mb/sec:
> 30.260630125485257
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 31.812650680541992
> 15/11/27 14:50:32 INFO fs.TestDFSIO: IO rate std deviation:
> 6.862839589024802
> 15/11/27 14:50:32 INFO fs.TestDFSIO: Test exec time sec: 705.559
>
> For the read phase:
> 15/11/27 14:56:46 INFO mapreduce.Job: Counters: 51
> File System Counters
> FILE: Number of bytes read=637
> FILE: Number of bytes written=929311
> FILE: Number of read operations=0
> FILE: Number of large read operations=0
> FILE: Number of write operations=0
> HDFS: Number of bytes read=120259085961
> HDFS: Number of bytes written=84
> HDFS: Number of read operations=38
> HDFS: Number of large read operations=0
> HDFS: Number of write operations=2
> Job Counters
> Killed map tasks=4
> Launched map tasks=11
> Launched reduce tasks=1
> Data-local map tasks=9
> Rack-local map tasks=2
> Total time spent by all maps in occupied slots (ms)=2096182
> Total time spent by all reduces in occupied slots (ms)=272737
> Total time spent by all map tasks (ms)=2096182
> Total time spent by all reduce tasks (ms)=272737
> Total vcore-seconds taken by all map tasks=2096182
> Total vcore-seconds taken by all reduce tasks=272737
> Total megabyte-seconds taken by all map tasks=2146490368
> Total megabyte-seconds taken by all reduce tasks=279282688
> Map-Reduce Framework
> Map input records=7
> Map output records=35
> Map output bytes=561
> Map output materialized bytes=673
> Input split bytes=889
> Combine input records=0
> Combine output records=0
> Reduce input groups=5
> Reduce shuffle bytes=673
> Reduce input records=35
> Reduce output records=5
> Spilled Records=70
> Shuffled Maps =7
> Failed Shuffles=0
> Merged Map outputs=7
> GC time elapsed (ms)=1407
> CPU time spent (ms)=96580
> Physical memory (bytes) snapshot=1945346048
> Virtual memory (bytes) snapshot=7420182528
> Total committed heap usage (bytes)=1421869056
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=784
> File Output Format Counters
> Bytes Written=84
> 15/11/27 14:56:46 INFO fs.TestDFSIO: ----- TestDFSIO ----- : read
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Date & time: Fri Nov 27
> 14:56:46 CET 2015
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Number of files: 7
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Total MBytes processed: 114688.0
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Throughput mb/sec:
> 101.66069077999725
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Average IO rate mb/sec:
> 153.29443359375
> 15/11/27 14:56:46 INFO fs.TestDFSIO: IO rate std deviation:
> 115.23795112362669
> 15/11/27 14:56:46 INFO fs.TestDFSIO: Test exec time sec: 370.396
>
> I usually average over a number of runs, but this is just a single one. I
> have seen much greater execution times for both the write and the read
> phases (up to 2x the ones stated above). I have compared the performance to
> XtreemFS, another distributed file system, and it achieves an average write
> rate that is around 6x faster, and an average read rate that is around 2.5x
> faster, however with a much lower standard deviation rate. Note that HDFS
> outperforms XtreemFS in terms of TestDFSIO benchmark results with smaller
> files (1G). I also don' understand why map tasks are being killed.
>
> I noticed that quite some time is spent on GC, so I plotted some system
> metrics for one node running a DataNode/NodeManager (the write phase stops
> and the read phase starts at around 14:51):
>
>
>
> I am wondering why the system RAM usage goes all the way up to the Yarn
> container limit of around 60G, when only one 16G file is being written
> to/read from on this node.
>
> So, to sum up a list of questions that I would like to ask your advice
> about:
>
> - Has anyone observed similar behavior/performance with HDFS and large
> files?
> - Which configuration parameters would I need to tweak in order to
> increase performance, or which system properties do I need to examine for
> you to give me helpful advice here?
> - Why is the RAM consumption so high?
> - Why is the reported standard deviation during read phases so high?
>
> Thanks in advance for your time and effort!
>
> Robert
>
> --
> My GPG Key ID: 336E2680
>