[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Arpit Agarwal updated HADOOP-16833:
---
Fix Version/s: 3.3.0
Target Version/s: (was: 3.3.0)
Resolution: Fixed
Status: Resolved (was: Patch Available)
Thanks for the contribution [~sodonnell]. I've committed this to trunk.
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Fix For: 3.3.0
>
> Attachments: HADOOP-16833.001.patch, HADOOP-16833.002.patch,
> HADOOP-16833.003.patch, HADOOP-16833.004.patch, HADOOP-16833.005.patch,
> HADOOP-16833.006.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Attachment: HADOOP-16833.006.patch
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch, HADOOP-16833.002.patch,
> HADOOP-16833.003.patch, HADOOP-16833.004.patch, HADOOP-16833.005.patch,
> HADOOP-16833.006.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Attachment: HADOOP-16833.005.patch
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch, HADOOP-16833.002.patch,
> HADOOP-16833.003.patch, HADOOP-16833.004.patch, HADOOP-16833.005.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Attachment: HADOOP-16833.004.patch
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch, HADOOP-16833.002.patch,
> HADOOP-16833.003.patch, HADOOP-16833.004.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Attachment: HADOOP-16833.003.patch
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch, HADOOP-16833.002.patch,
> HADOOP-16833.003.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Attachment: HADOOP-16833.002.patch
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch, HADOOP-16833.002.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Status: Patch Available (was: Open)
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
[jira] [Updated] (HADOOP-16833) InstrumentedLock should log lock queue time
[
https://issues.apache.org/jira/browse/HADOOP-16833?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stephen O'Donnell updated HADOOP-16833:
---
Attachment: HADOOP-16833.001.patch
> InstrumentedLock should log lock queue time
> ---
>
> Key: HADOOP-16833
> URL: https://issues.apache.org/jira/browse/HADOOP-16833
> Project: Hadoop Common
> Issue Type: Improvement
> Components: util
>Affects Versions: 3.3.0
>Reporter: Stephen O'Donnell
>Assignee: Stephen O'Donnell
>Priority: Major
> Attachments: HADOOP-16833.001.patch
>
>
> Within the Datanode, we often see contention around the FsDatasetImpl lock.
> This can be for various reasons, eg the DN is under IO load, and other bugs,
> eg HDFS-15131.
> When DN slow downs happen, it is very difficult to debug what is causing it,
> as there are few messages in the logs which indicate what is happening.
> In my experience, the presence of this log is informative:
> {code}
> 2019-11-27 09:00:49,678 INFO org.apache.hadoop.hdfs.server.datanode.DataNode:
> Took 21540ms to process 1 commands from NN
> {code}
> This comes from the datanode heartbeat thread, and it is logged when the
> commands returned from the heartbeat cannot be enqueued, and usually this is
> because the thread cannot get the FsDatasetImpl lock due to contention with
> other slow threads.
> HDFS-14997 moved the command processing to an async thread, and hence this
> useful message will disappear.
> InstrumentedLock introduced a feature to the datanode, where it will log a
> stack trace if any thread holds the lock for over 300ms. However this will
> not catch a scenario where 10 threads each hold a lock for 200ms, leading to
> the next in the queue having waited over 2 seconds.
> I believe it would be useful to extend InstrumentedLock to log if a thread
> has to wait for over some threshold. That way, we could be able to catch
> scenarios like the heartbeat thread shows us, but in a much more obvious way,
> provided lock contention is involved.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
