Amazon EMR allows you to define scale-out and scale-in rules to automatically add and remove instances based on the metrics you specify.
In this article I am going to explore the instance controller logs that can be very useful in monitoring the auto-scaling. The logs are located in /emr/instance-controller/log/ directory on the EMR master node.
The instance controller gets updates about the cluster instance states almost every 30 seconds so you can see all changes in your EMR cluster.
Active Hadoop Nodes
The log provides the summary about the active nodes in Hadoop:
2019-05-16 11:00:06,283 INFO Poller: Active hadoop slave number: 3 2019-05-16 11:00:06,287 INFO Poller: InstanceJointStatusMap contains 82 entries (L:79 R:3)
When a node is removed from the EMR cluster configured for auto-scaling it is marked as Lost – (L:79 R:3) specifies 79 Lost and 3 Running nodes. That’s why you can see a large number of Lost nodes in a cluster with auto-scaling.
New nodes can be already running, but not registered in Hadoop YARN yet (active nodes 3, 77 lost and 18 running):
2019-05-16 11:45:22,654 INFO Poller: Active hadoop slave number: 3 2019-05-16 11:45:22,659 INFO Poller: InstanceJointStatusMap contains 95 entries (L:77 R:18)
New nodes are fully added:
2019-05-16 11:46:31,948 INFO Poller: Active hadoop slave number: 43 2019-05-16 11:46:31,954 INFO Poller: InstanceJointStatusMap contains 115 entries (L:72 R:43)
The cluster has started reducing the number of instances (numTargetNodes:23 numActiveNodes:43 – removing 20 instances from the cluster):
2019-05-16 11:55:25,391 INFO Poller: Core - 2 numTargetNodes:23 numActiveNodes:43 2019-05-16 11:55:28,354 INFO Poller: Active hadoop slave number: 23 2019-05-16 11:55:28,359 INFO Poller: InstanceJointStatusMap contains 116 entries (L:72 R:38 DN:3 DD:2)
Above you can see that although Hadoop already has 23 nodes, 38 EC2 instances are still running, 3 instances are decommissioning, and 2 decommissioned (DN:3 DD:2).
A few minutes later (17 nodes decommissioned, 3 are still decommissioning):
2019-05-16 11:58:48,130 INFO Poller: Active hadoop slave number: 23 2019-05-16 11:58:48,135 INFO Poller: InstanceJointStatusMap contains 116 entries (L:73 R:23 DD:17 DN:3)
And finally when the downsizing is complete:
2019-05-16 12:16:25,769 INFO Poller: Active hadoop slave number: 23 2019-05-16 12:16:25,775 INFO Poller: InstanceJointStatusMap contains 116 entries (L:93 R:23)
Instance Status
Besides the summary information about the instances, the instance controller also logs the details for every instance:
<id1> 2h18m L 1h11m ig-1T <ip1> I: 1h22m Y:L 1h25m c: 0 am: 0 H:DEAD T:-82m <id2> 2h18m R 2h17m ig-1T <ip2> I: 38s Y:R 104s c: 0 am:53248 H:R 0.2% <id3> 2h18m R 2h17m ig-1T <ip3> I: 39s Y:R 104s c: 0 am:53248 H:R 0.2% <id4> 2h18m R 2h17m ig-1T <ip4> I: 38s Y:R 103s c: 0 am:53248 H:R 0.2% ...
An EMR instance can be in one of the following Joint Status: RUNNING: R, IDLE: ID, STARTING: S, DECOMMISSIONING: DN, DECOMMISSIONED: DD, FAILED: F, LOST: L
Every instance runs a YARN NodeManager that can have the status as follows (Y:x): NEW: N, RUNNING: R, UNHEALTHY: U, DECOMISSIONING or DECOMISSIONED: D, LOST: L, REBOOTED: B
Additionally if the instance runs a HDFS DataNode it can be in the following status (H:x):
RUNNING: R, DECOMISSIONING: N, DECOMISSIONED: D
For example:
<id2> 2h18m R 2h17m ig-1T <ip2> I: 38s Y:R 104s c: 29 am:53248 H:R 5.9%
id2 => EC2 Instance Id
2h18m => Time since instance controller check-in
R => Running status
1h29m => JointStateChangeTime
ig-1T => EMR Instance group
ip2 => EC2 hostname
I: 38s => Time from last instance controller check-in
Y: R => YarnNode Status, R is Running
104s => Last Health Update Time
c:29 => 29 containers
am: => Available Memory(MB) 53248 MB
H:R => DataNode Status, R is Running
5.9% => 5.9% DFS Used Percentage. ("DFS Used%" from the result of "hdfs dfsadmin -report" command)
Scale-Out in Detail
Now let’s review how EMR logs adding instances to the cluster. In my case, the auto-scale rule is to add 40 Core instances (nodes with HDFS) running on dedicated EC2 instances.
Here is the first message indicating that the number of nodes is being increased from 3 to 43:
2019-05-16 11:44:16,631 INFO Poller: Core - 2 numTargetNodes:43 numActiveNodes:3
Then EMR created 40 instances (less than 30 seconds for create requests and obtaining instance IDs):
2019-05-16 11:45:16,679 INFO 2036811976@mrpc-273: creates RemoteInstanceState i-0ef1... 2019-05-16 11:45:17,527 INFO 2036811976@mrpc-273: creates RemoteInstanceState i-01ff... ... 2019-05-16 11:45:44,955 INFO 1592373994@mrpc-276: creates RemoteInstanceState i-0d92b...
EMR makes some corrections if the new instances take the same IP addresses that were assigned to lost nodes:
2019-05-16 11:45:20,703 INFO Poller: Detected legacy:i-0d797 active:i-058c for ip1.ec2.internal 2019-05-16 11:45:20,703 INFO Poller: Delete RemoteInstanceState rows i-0d797 2019-05-16 11:45:20,705 INFO Poller: Delete SlaveRecordDbRow rows i-0d797
Next, EMR registers the new instances in its internal HSQLDB database:
2019-05-16 11:45:22,653 INFO Poller: Create SlaveRecordDbRow for i-058c... 2019-05-16 11:45:22,654 INFO Poller: Create SlaveRecordDbRow for i-01ff... ... 2019-05-16 11:46:31,947 INFO Poller: Create SlaveRecordDbRow for i-0af87...
And finally the new instances change their state to RUNNING:
2019-05-16 11:45:23,513 INFO Poller: Update i-01ff InstanceState STARTING => RUNNING 2019-05-16 11:45:23,514 INFO Poller: Update i-0311 InstanceState STARTING => RUNNING ... 2019-05-16 11:45:57,959 INFO Poller: Update i-0fe2 InstanceState STARTING => RUNNING 2019-05-16 11:46:31,948 INFO Poller: Active hadoop slave number: 43
You can see that it took about 2 minutes to add 40 instances.
There are much more information in the instance controller logs that can be helpful to setup an advanced monitoring of your EMR clusters.