[
https://issues.apache.org/jira/browse/NIFI-16479?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Anshu Singh updated NIFI-16479:
-------------------------------
Description:
h3. Summary
Copying components in the UI (Ctrl+C, which calls {{{}POST
/nifi-api/process-groups/\{id}/copy{}}}) runs
{{StandardNiFiServiceFacade.copyComponents}} while holding the node-wide
*write* lock of {{{}NiFiServiceFacadeLock{}}}. Every other API call on that
node has to wait until the copy finishes. This includes the UI polling calls
{{{}/flow/current-user{}}}, {{{}/flow/status{}}},
{{/flow/controller/bulletins}} and {{{}/flow/process-groups/{id{}}}}. In a
cluster, the other nodes replicate those GETs to the copying node, hit
{{{}nifi.cluster.node.read.timeout{}}}, and the UI shows:
{noformat}
Invalid State
Current User Entity not expected
[org.apache.nifi.web.client.api.WebClientServiceException: Request execution
failed HTTP Method [GET] URI
[https://<copying-node>:8443/nifi-api/flow/current-user]]
{noformat}
With large parameter contexts a single copy can take more than a minute, so the
whole cluster UI becomes unusable for that time.
The {{copy*}} write-lock pointcut and {{copyComponents}} are unchanged in
2.12.0 and on main (verified in source). Line numbers below are from 2.8.0.
h3. Why this looks unintended
* {{NiFiServiceFacadeLock}} applies the write lock by method-name pointcut:
{{execution(* copy*(..))}} -> {{{}proceedWithWriteLock{}}}. The same pointcut
already exists in 1.x, where {{copy*}} matched {{{}copySnippet{}}}, which does
create components and calls {{{}controllerFacade.save(){}}}.
* NIFI-13976 (PR #9535) added the new {{copyComponents}} method for the 2.x
copy/paste endpoints. {{NiFiServiceFacadeLock}} was not changed, so
{{copyComponents}} inherited the write lock only because of its name.
* {{copyComponents}} (StandardNiFiServiceFacade, 2.8.0 ~line 5295) only reads.
It calls {{{}processGroupDAO.getProcessGroup{}}},
{{NiFiRegistryFlowMapper.mapProcessGroup}} and
{{{}NiFiRegistryFlowMapper.mapParameterContexts{}}}, then builds a
{{{}CopyResponseEntity{}}}. It does not save the flow, does not claim or update
revisions, and does not modify components.
* The mutating counterpart, {{pasteComponents}} (~line 6317), does not match
any {{NiFiServiceFacadeLock}} pointcut (there is no {{{}paste*{}}}). It is
protected by {{revisionManager.updateRevision}} and process group locks. So the
write lock on copy does not protect paste either.
* Download Flow Definition ({{{}getCurrentFlowSnapshotByGroupId{}}}, a
{{get*}} method, so *read* lock) already runs the same {{mapParameterContexts}}
mapping under the read lock.
h3. Evidence
Thread dump of the copying node during the stall (NiFi 2.8.0). One writer and
five UI requests are parked on the same lock:
{noformat}
"NiFi Web Server-104441" ... runnable
java.lang.Thread.State: RUNNABLE
at
org.apache.nifi.parameter.StandardParameterReferenceManager.getReferencedControllerServiceData(StandardParameterReferenceManager.java:125)
at
org.apache.nifi.registry.flow.mapping.NiFiRegistryFlowMapper.mapParameterContexts(NiFiRegistryFlowMapper.java:876)
at
org.apache.nifi.web.StandardNiFiServiceFacade.copyComponents(StandardNiFiServiceFacade.java:5361)
at
org.apache.nifi.web.NiFiServiceFacadeLock.proceedWithWriteLock(NiFiServiceFacadeLock.java:179)
at
org.apache.nifi.web.NiFiServiceFacadeLock.copyLock(NiFiServiceFacadeLock.java:78)
at
org.apache.nifi.web.api.ProcessGroupResource.copy(ProcessGroupResource.java:409)
"NiFi Web Server-106846" ... waiting on condition
- parking to wait for <0x000000060ce26018> (a
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
at
org.apache.nifi.web.NiFiServiceFacadeLock.proceedWithReadLock(NiFiServiceFacadeLock.java:158)
at
org.apache.nifi.web.api.FlowResource.getControllerStatus(FlowResource.java:1505)
(same for FlowResource.getBulletins, getFlow, getCurrentUser,
getRegistryClients)
{noformat}
Log on another node (the requester) during the same window:
{noformat}
WARN [Replicate Request Thread-4625] o.a.n.c.c.h.r.ThreadPoolRequestReplicator
Failed to replicate request GET /nifi-api/flow/current-user to al2023-node5:8443
org.apache.nifi.web.client.api.WebClientServiceException: Request execution
failed HTTP Method [GET] URI
[https://al2023-node5:8443/nifi-api/flow/current-user]
Caused by: java.net.http.HttpTimeoutException: request timed out
{noformat}
Lock timing measured with {{<logger
name="org.apache.nifi.web.NiFiServiceFacadeLock" level="DEBUG"/>}} (lab, NiFi
2.6.0):
||Scenario||copyComponents write-lock hold||Effect||
|~16.5k processors, 1,600 small contexts, copy 1 top-level group|2.0 s|reads
waited 1.4-1.6 s, no errors|
|same, plus a shared 100-parameter context inherited by all groups, copy all 13
top-level groups|71.2 s|47 reads waited more than 15 s (max 69.8 s); 31 of 373
UI requests failed with 409/500 WebClientServiceException|
|3,005 groups, ~14.7k processors, 11 contexts (1,645 parameters) bound to all
groups, copy *one* group, no other load|50-82 s|UI on the other nodes shows
"Invalid State" for about 1 minute and recovers when the copy ends|
Raising {{nifi.cluster.node.read.timeout}} to 300 s,
{{nifi.web.request.timeout}} to 420 s and the thread counts to 1000/150 only
hides the error. UI requests then hang for about 80 s instead of failing.
h3. Steps to reproduce
# 3-node cluster with {{{}nifi.cluster.node.read.timeout=20 sec{}}}.
# Create ~3,000 nested process groups with ~15,000 processors. Bind one
parameter context to every group; that context inherits ~10 contexts with
100-200 parameters each.
# Open the UI on node A. On node B, select one top-level process group and
press Ctrl+C.
# Within 20 s, node A's UI shows "Invalid State ... WebClientServiceException
... node B" until the copy on node B completes.
h3. Expected
Copying is read-only and should not block other readers. It should take the
read lock (as Download Flow Definition does), so only flow modifications wait
for it.
h3. Suggested fix
Restrict the write-lock pointcut to {{copySnippet}} and let {{copyComponents}}
use {{{}proceedWithReadLock{}}}. Alternatives: an explicit read pointcut for
{{{}copyComponents{}}}, or renaming the facade method so it no longer matches
{{{}copy*{}}}.
h3. Related
The cost of the copy itself (mapping the whole parent group, and a full-flow
scan per parameter) is tracked separately in NIFI-16480.
.
was:
h3. Summary
Copying components in the UI (Ctrl+C, which calls {{POST
/nifi-api/process-groups/\{id\}/copy}}) runs
{{StandardNiFiServiceFacade.copyComponents}} while holding the node-wide
*write* lock of {{NiFiServiceFacadeLock}}. Every other API call on that node
has to wait until the copy finishes. This includes the UI polling calls
{{/flow/current-user}}, {{/flow/status}}, {{/flow/controller/bulletins}} and
{{/flow/process-groups/\{id\}}}. In a cluster, the other nodes replicate those
GETs to the copying node, hit {{nifi.cluster.node.read.timeout}}, and the UI
shows:
{noformat}
Invalid State
Current User Entity not expected
[org.apache.nifi.web.client.api.WebClientServiceException: Request execution
failed HTTP Method [GET] URI
[https://<copying-node>:8443/nifi-api/flow/current-user]]
{noformat}
With large parameter contexts a single copy can take more than a minute, so the
whole cluster UI becomes unusable for that time.
The {{copy*}} write-lock pointcut and {{copyComponents}} are unchanged in
2.12.0 and on main (verified in source). Line numbers below are from 2.8.0.
h3. Why this looks unintended
* {{NiFiServiceFacadeLock}} applies the write lock by method-name pointcut:
{{execution(* copy*(..))}} -> {{proceedWithWriteLock}}. The same pointcut
already exists in 1.x, where {{copy*}} matched {{copySnippet}}, which does
create components and calls {{controllerFacade.save()}}.
* NIFI-13976 (PR #9535) added the new {{copyComponents}} method for the 2.x
copy/paste endpoints. {{NiFiServiceFacadeLock}} was not changed, so
{{copyComponents}} inherited the write lock only because of its name.
* {{copyComponents}} (StandardNiFiServiceFacade, 2.8.0 ~line 5295) only reads.
It calls {{processGroupDAO.getProcessGroup}},
{{NiFiRegistryFlowMapper.mapProcessGroup}} and
{{NiFiRegistryFlowMapper.mapParameterContexts}}, then builds a
{{CopyResponseEntity}}. It does not save the flow, does not claim or update
revisions, and does not modify components.
* The mutating counterpart, {{pasteComponents}} (~line 6317), does not match
any {{NiFiServiceFacadeLock}} pointcut (there is no {{paste*}}). It is
protected by {{revisionManager.updateRevision}} and process group locks. So the
write lock on copy does not protect paste either.
* Download Flow Definition ({{getCurrentFlowSnapshotByGroupId}}, a {{get*}}
method, so *read* lock) already runs the same {{mapParameterContexts}} mapping
under the read lock.
h3. Evidence
Thread dump of the copying node during the stall (NiFi 2.8.0). One writer and
five UI requests are parked on the same lock:
{noformat}
"NiFi Web Server-104441" ... runnable
java.lang.Thread.State: RUNNABLE
at
org.apache.nifi.parameter.StandardParameterReferenceManager.getReferencedControllerServiceData(StandardParameterReferenceManager.java:125)
at
org.apache.nifi.registry.flow.mapping.NiFiRegistryFlowMapper.mapParameterContexts(NiFiRegistryFlowMapper.java:876)
at
org.apache.nifi.web.StandardNiFiServiceFacade.copyComponents(StandardNiFiServiceFacade.java:5361)
at
org.apache.nifi.web.NiFiServiceFacadeLock.proceedWithWriteLock(NiFiServiceFacadeLock.java:179)
at
org.apache.nifi.web.NiFiServiceFacadeLock.copyLock(NiFiServiceFacadeLock.java:78)
at
org.apache.nifi.web.api.ProcessGroupResource.copy(ProcessGroupResource.java:409)
"NiFi Web Server-106846" ... waiting on condition
- parking to wait for <0x000000060ce26018> (a
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
at
org.apache.nifi.web.NiFiServiceFacadeLock.proceedWithReadLock(NiFiServiceFacadeLock.java:158)
at
org.apache.nifi.web.api.FlowResource.getControllerStatus(FlowResource.java:1505)
(same for FlowResource.getBulletins, getFlow, getCurrentUser,
getRegistryClients)
{noformat}
Log on another node (the requester) during the same window:
{noformat}
WARN [Replicate Request Thread-4625] o.a.n.c.c.h.r.ThreadPoolRequestReplicator
Failed to replicate request GET /nifi-api/flow/current-user to al2023-node5:8443
org.apache.nifi.web.client.api.WebClientServiceException: Request execution
failed HTTP Method [GET] URI
[https://al2023-node5:8443/nifi-api/flow/current-user]
Caused by: java.net.http.HttpTimeoutException: request timed out
{noformat}
Lock timing measured with {{<logger
name="org.apache.nifi.web.NiFiServiceFacadeLock" level="DEBUG"/>}} (lab, NiFi
2.6.0):
||Scenario||copyComponents write-lock hold||Effect||
|~16.5k processors, 1,600 small contexts, copy 1 top-level group|2.0 s|reads
waited 1.4-1.6 s, no errors|
|same, plus a shared 100-parameter context inherited by all groups, copy all 13
top-level groups|71.2 s|47 reads waited more than 15 s (max 69.8 s); 31 of 373
UI requests failed with 409/500 WebClientServiceException|
|3,005 groups, ~14.7k processors, 11 contexts (1,645 parameters) bound to all
groups, copy *one* group, no other load|50-82 s|UI on the other nodes shows
"Invalid State" for about 1 minute and recovers when the copy ends|
Raising {{nifi.cluster.node.read.timeout}} to 300 s,
{{nifi.web.request.timeout}} to 420 s and the thread counts to 1000/150 only
hides the error. UI requests then hang for about 80 s instead of failing.
h3. Steps to reproduce
# 3-node cluster with {{nifi.cluster.node.read.timeout=20 sec}}.
# Create ~3,000 nested process groups with ~15,000 processors. Bind one
parameter context to every group; that context inherits ~10 contexts with
100-200 parameters each.
# Open the UI on node A. On node B, select one top-level process group and
press Ctrl+C.
# Within 20 s, node A's UI shows "Invalid State ... WebClientServiceException
... node B" until the copy on node B completes.
h3. Expected
Copying is read-only and should not block other readers. It should take the
read lock (as Download Flow Definition does), so only flow modifications wait
for it.
h3. Suggested fix
Restrict the write-lock pointcut to {{copySnippet}} and let {{copyComponents}}
use {{proceedWithReadLock}}. Alternatives: an explicit read pointcut for
{{copyComponents}}, or renaming the facade method so it no longer matches
{{copy*}}.
h3. Related
The cost of the copy itself (mapping the whole parent group, and a full-flow
scan per parameter) is tracked separately in <TICKET-2-KEY>.
> Copy request (POST /process-groups/{id}/copy) holds the NiFiServiceFacadeLock
> write lock, blocking all API requests on the node
> -------------------------------------------------------------------------------------------------------------------------------
>
> Key: NIFI-16479
> URL: https://issues.apache.org/jira/browse/NIFI-16479
> Project: Apache NiFi
> Issue Type: Bug
> Components: Core Framework
> Affects Versions: 2.6.0, 2.7.0, 2.8.0, 2.9.0, 2.10.0, 2.11.0, 2.12.0
> Environment: 3-node NiFi cluster (NiFi 2.6.0 lab, issue also observed
> on NiFi 2.8.0), Java 21, 4 vCPU / 16 GB RAM per node, 8 GB heap, external
> ZooKeeper, nifi.cluster.node.read.timeout=20 sec. Flow: ~3,000 process
> groups, ~15,000 processors, parameter contexts with inheritance (one context
> bound to every process group, 1,645 parameters reachable).
> Reporter: Anshu Singh
> Priority: Major
> Labels: cluster, copypaste, core, locking, performance
>
> h3. Summary
> Copying components in the UI (Ctrl+C, which calls {{{}POST
> /nifi-api/process-groups/\{id}/copy{}}}) runs
> {{StandardNiFiServiceFacade.copyComponents}} while holding the node-wide
> *write* lock of {{{}NiFiServiceFacadeLock{}}}. Every other API call on that
> node has to wait until the copy finishes. This includes the UI polling calls
> {{{}/flow/current-user{}}}, {{{}/flow/status{}}},
> {{/flow/controller/bulletins}} and {{{}/flow/process-groups/{id{}}}}. In a
> cluster, the other nodes replicate those GETs to the copying node, hit
> {{{}nifi.cluster.node.read.timeout{}}}, and the UI shows:
> {noformat}
> Invalid State
> Current User Entity not expected
> [org.apache.nifi.web.client.api.WebClientServiceException: Request execution
> failed HTTP Method [GET] URI
> [https://<copying-node>:8443/nifi-api/flow/current-user]]
> {noformat}
> With large parameter contexts a single copy can take more than a minute, so
> the whole cluster UI becomes unusable for that time.
> The {{copy*}} write-lock pointcut and {{copyComponents}} are unchanged in
> 2.12.0 and on main (verified in source). Line numbers below are from 2.8.0.
> h3. Why this looks unintended
> * {{NiFiServiceFacadeLock}} applies the write lock by method-name pointcut:
> {{execution(* copy*(..))}} -> {{{}proceedWithWriteLock{}}}. The same pointcut
> already exists in 1.x, where {{copy*}} matched {{{}copySnippet{}}}, which
> does create components and calls {{{}controllerFacade.save(){}}}.
> * NIFI-13976 (PR #9535) added the new {{copyComponents}} method for the 2.x
> copy/paste endpoints. {{NiFiServiceFacadeLock}} was not changed, so
> {{copyComponents}} inherited the write lock only because of its name.
> * {{copyComponents}} (StandardNiFiServiceFacade, 2.8.0 ~line 5295) only
> reads. It calls {{{}processGroupDAO.getProcessGroup{}}},
> {{NiFiRegistryFlowMapper.mapProcessGroup}} and
> {{{}NiFiRegistryFlowMapper.mapParameterContexts{}}}, then builds a
> {{{}CopyResponseEntity{}}}. It does not save the flow, does not claim or
> update revisions, and does not modify components.
> * The mutating counterpart, {{pasteComponents}} (~line 6317), does not match
> any {{NiFiServiceFacadeLock}} pointcut (there is no {{{}paste*{}}}). It is
> protected by {{revisionManager.updateRevision}} and process group locks. So
> the write lock on copy does not protect paste either.
> * Download Flow Definition ({{{}getCurrentFlowSnapshotByGroupId{}}}, a
> {{get*}} method, so *read* lock) already runs the same
> {{mapParameterContexts}} mapping under the read lock.
> h3. Evidence
> Thread dump of the copying node during the stall (NiFi 2.8.0). One writer and
> five UI requests are parked on the same lock:
> {noformat}
> "NiFi Web Server-104441" ... runnable
> java.lang.Thread.State: RUNNABLE
> at
> org.apache.nifi.parameter.StandardParameterReferenceManager.getReferencedControllerServiceData(StandardParameterReferenceManager.java:125)
> at
> org.apache.nifi.registry.flow.mapping.NiFiRegistryFlowMapper.mapParameterContexts(NiFiRegistryFlowMapper.java:876)
> at
> org.apache.nifi.web.StandardNiFiServiceFacade.copyComponents(StandardNiFiServiceFacade.java:5361)
> at
> org.apache.nifi.web.NiFiServiceFacadeLock.proceedWithWriteLock(NiFiServiceFacadeLock.java:179)
> at
> org.apache.nifi.web.NiFiServiceFacadeLock.copyLock(NiFiServiceFacadeLock.java:78)
> at
> org.apache.nifi.web.api.ProcessGroupResource.copy(ProcessGroupResource.java:409)
> "NiFi Web Server-106846" ... waiting on condition
> - parking to wait for <0x000000060ce26018> (a
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
> at
> org.apache.nifi.web.NiFiServiceFacadeLock.proceedWithReadLock(NiFiServiceFacadeLock.java:158)
> at
> org.apache.nifi.web.api.FlowResource.getControllerStatus(FlowResource.java:1505)
> (same for FlowResource.getBulletins, getFlow, getCurrentUser,
> getRegistryClients)
> {noformat}
> Log on another node (the requester) during the same window:
> {noformat}
> WARN [Replicate Request Thread-4625]
> o.a.n.c.c.h.r.ThreadPoolRequestReplicator Failed to replicate request GET
> /nifi-api/flow/current-user to al2023-node5:8443
> org.apache.nifi.web.client.api.WebClientServiceException: Request execution
> failed HTTP Method [GET] URI
> [https://al2023-node5:8443/nifi-api/flow/current-user]
> Caused by: java.net.http.HttpTimeoutException: request timed out
> {noformat}
> Lock timing measured with {{<logger
> name="org.apache.nifi.web.NiFiServiceFacadeLock" level="DEBUG"/>}} (lab, NiFi
> 2.6.0):
> ||Scenario||copyComponents write-lock hold||Effect||
> |~16.5k processors, 1,600 small contexts, copy 1 top-level group|2.0 s|reads
> waited 1.4-1.6 s, no errors|
> |same, plus a shared 100-parameter context inherited by all groups, copy all
> 13 top-level groups|71.2 s|47 reads waited more than 15 s (max 69.8 s); 31 of
> 373 UI requests failed with 409/500 WebClientServiceException|
> |3,005 groups, ~14.7k processors, 11 contexts (1,645 parameters) bound to all
> groups, copy *one* group, no other load|50-82 s|UI on the other nodes shows
> "Invalid State" for about 1 minute and recovers when the copy ends|
> Raising {{nifi.cluster.node.read.timeout}} to 300 s,
> {{nifi.web.request.timeout}} to 420 s and the thread counts to 1000/150 only
> hides the error. UI requests then hang for about 80 s instead of failing.
> h3. Steps to reproduce
> # 3-node cluster with {{{}nifi.cluster.node.read.timeout=20 sec{}}}.
> # Create ~3,000 nested process groups with ~15,000 processors. Bind one
> parameter context to every group; that context inherits ~10 contexts with
> 100-200 parameters each.
> # Open the UI on node A. On node B, select one top-level process group and
> press Ctrl+C.
> # Within 20 s, node A's UI shows "Invalid State ...
> WebClientServiceException ... node B" until the copy on node B completes.
> h3. Expected
> Copying is read-only and should not block other readers. It should take the
> read lock (as Download Flow Definition does), so only flow modifications wait
> for it.
> h3. Suggested fix
> Restrict the write-lock pointcut to {{copySnippet}} and let
> {{copyComponents}} use {{{}proceedWithReadLock{}}}. Alternatives: an explicit
> read pointcut for {{{}copyComponents{}}}, or renaming the facade method so it
> no longer matches {{{}copy*{}}}.
> h3. Related
> The cost of the copy itself (mapping the whole parent group, and a full-flow
> scan per parameter) is tracked separately in NIFI-16480.
> .
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
