[MAPREDUCE-7319] Log list of mappers at trace level in ShuffleHandler audit log

• Type: Improvement
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 3.4.0
• Fix Version/s: 3.4.0, 3.3.1, 2.10.2, 3.2.3
• Component/s: yarn
• Assignee: Jim Brennan
• Reporter: Jim Brennan
• Created: 08/Feb/21 17:20
• Updated: 10/Jun/21 08:11
• Resolved: 09/Feb/21 19:37

Description

MAPREDUCE-6958 added the content length to ShuffleHandler audit log, which is logged at DEBUG level. After enabling it, we found that the list of mappers for large jobs was filling up our audit logs. It would be good to move the list of mappers to TRACE level to reduce the logging impact without disabling the log message entirely.

For example a log message like this:

2018-01-25 23:43:02,669 [New I/O worker #1] DEBUG ShuffleHandler.audit: shuffle for job_1512479762132_1318600 reducer 241 length 482072 mappers: [attempt_1512479762132_1318600_1_00_004852_0_10003,
attempt_1512479762132_1318600_1_00_004190_0_10003, attempt_1512479762132_1318600_1_00_004393_0_10003, attempt_1512479762132_1318600_1_00_005057_0_10003, attempt_1512479762132_1318600_1_00_004855_0_10002,
attempt_1512479762132_1318600_1_00_003976_0_10003, attempt_1512479762132_1318600_1_00_004058_0_10003, attempt_1512479762132_1318600_1_00_004355_0_10003, attempt_1512479762132_1318600_1_00_004436_0_10002,
attempt_1512479762132_1318600_1_00_004854_0_10003, attempt_1512479762132_1318600_1_00_005174_0_10004, attempt_1512479762132_1318600_1_00_003972_0_10002, attempt_1512479762132_1318600_1_00_004853_0_10002,
attempt_1512479762132_1318600_1_00_004856_0_10002]

Would become this with log4j.logger.org.apache.hadoop.mapred.ShuffleHandler.audit=DEBUG:

2018-01-25 23:43:02,669 [New I/O worker #1] DEBUG ShuffleHandler.audit: shuffle for job_1512479762132_1318600 reducer 241 length 482072

And this with log4j.logger.org.apache.hadoop.mapred.ShuffleHandler.audit=TRACE:

2018-01-25 23:43:02,669 [New I/O worker #1] DEBUG ShuffleHandler.audit: shuffle for job_1512479762132_1318600 reducer 241 length 482072
2018-01-25 23:43:02,669 [New I/O worker #1] TRACE ShuffleHandler.audit: shuffle for job_1512479762132_1318600 mappers: [attempt_1512479762132_1318600_1_00_004852_0_10003,
attempt_1512479762132_1318600_1_00_004190_0_10003, attempt_1512479762132_1318600_1_00_004393_0_10003, attempt_1512479762132_1318600_1_00_005057_0_10003, attempt_1512479762132_1318600_1_00_004855_0_10002,
attempt_1512479762132_1318600_1_00_003976_0_10003, attempt_1512479762132_1318600_1_00_004058_0_10003, attempt_1512479762132_1318600_1_00_004355_0_10003, attempt_1512479762132_1318600_1_00_004436_0_10002,
attempt_1512479762132_1318600_1_00_004854_0_10003, attempt_1512479762132_1318600_1_00_005174_0_10004, attempt_1512479762132_1318600_1_00_003972_0_10002, attempt_1512479762132_1318600_1_00_004853_0_10002,
attempt_1512479762132_1318600_1_00_004856_0_10002]

One question is whether there are any downstream consumers of this audit log that might have a problem with this change?