You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@ranger.apache.org by "ruiliang (Jira)" <ji...@apache.org> on 2021/11/15 13:38:00 UTC
[jira] [Updated] (RANGER-3513) locks getLatestOrCached(RangerServicePoliciesCache.java:198)
[ https://issues.apache.org/jira/browse/RANGER-3513?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
ruiliang updated RANGER-3513:
-----------------------------
Summary: locks getLatestOrCached(RangerServicePoliciesCache.java:198) (was: locks getLatestOrCached(RangerServicePoliciesCache.java:198) (ranger 1.2))
> locks getLatestOrCached(RangerServicePoliciesCache.java:198)
> ------------------------------------------------------------
>
> Key: RANGER-3513
> URL: https://issues.apache.org/jira/browse/RANGER-3513
> Project: Ranger
> Issue Type: Bug
> Components: admin
> Affects Versions: 1.2.0
> Reporter: ruiliang
> Priority: Major
> Attachments: ranger_1_1115.jstack
>
> Original Estimate: 12h
> Remaining Estimate: 12h
>
> add new policy ，All Ranger requests are 10s+.Print jstatck: some threads are locked.Does the external request lastKnownVersion not change?
> * top 61905 Threads cpu use 99.3%
> {code:java}
> KiB Swap: 0 total, 0 free, 0 used. 57020896 avail Mem
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> 61905 root 20 0 20.748g 4.689g 23760 R 99.3 7.6 4:32.52 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 3500 root 20 0 20.748g 4.689g 23760 S 8.3 7.6 0:00.31 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 45584 root 20 0 20.748g 4.689g 23760 S 6.3 7.6 0:02.76 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 62387 root 20 0 20.748g 4.689g 23760 S 6.3 7.6 0:02.32 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 7230 root 20 0 20.748g 4.689g 23760 S 5.3 7.6 0:00.42 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 3412 root 20 0 20.748g 4.689g 23760 S 5.0 7.6 0:00.53 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 45616 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:03.50 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 3498 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:00.92 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 7238 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:00.28 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 7096 root 20 0 20.748g 4.689g 23760 S 1.3 7.6 0:00.05 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52641 root 20 0 20.748g 4.689g 23760 S 0.3 7.6 1:33.20 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 7229 root 20 0 20.748g 4.689g 23760 S 0.3 7.6 0:00.30 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52032 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 0:00.00 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52034 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 0:00.84 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52035 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:40.21 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52036 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.32 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52037 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:36.96 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52038 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.96 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52039 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.80 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52040 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.05 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52041 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.59 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52042 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.29 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52043 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.88 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52044 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:39.19 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> 52045 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.46 java -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root -Dhostname=fs-hiido-range+
> root@fs-hiido-ranger-21-117-150:/home/liangrui# printf "%x\n" 61905
> f1d1
> root@fs-hiido-ranger-21-117-150:/home/liangrui#
> root@fs-hiido-ranger-21-117-150:/home/liangrui# jstack 52032 | grep -20 f1d1
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)
> "http-bio-6080-exec-9692" #9852 daemon prio=5 os_prio=0 tid=0x00007f0bf003a800 nid=0xf3b2 waiting on condition [0x00007f0c287cc000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000006c72df908> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
> at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:86)
> at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:32)
> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)
> "Thread-114" #9851 daemon prio=5 os_prio=0 tid=0x00007f0a14006800 nid=0xf1d1 runnable [0x00007f0c295d7000]
> java.lang.Thread.State: RUNNABLE
> at java.lang.reflect.Field.get(Field.java:393)
> at org.eclipse.persistence.internal.descriptors.InstanceVariableAttributeAccessor.getAttributeValueFromObject(InstanceVariableAttributeAccessor.java:76)
> at org.eclipse.persistence.mappings.DatabaseMapping.getAttributeValueFromObject(DatabaseMapping.java:630)
> at org.eclipse.persistence.mappings.foundation.AbstractDirectMapping.valueFromObject(AbstractDirectMapping.java:1176)
> at org.eclipse.persistence.internal.descriptors.ObjectBuilder.extractPrimaryKeyFromObject(ObjectBuilder.java:3011)
> at org.eclipse.persistence.internal.descriptors.ObjectBuilder.createObjectChangeSet(ObjectBuilder.java:2885)
> at org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.createObjectChangeSetThroughComparison(DeferredChangeDetectionPolicy.java:155)
> at org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.createObjectChangeSet(DeferredChangeDetectionPolicy.java:146)
> at org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.calculateChanges(DeferredChangeDetectionPolicy.java:91)
> at org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.calculateChangesForExistingObject(DeferredChangeDetectionPolicy.java:56)
> at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:664)
> at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:438)
> at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:863)
> at org.eclipse.persistence.internal.jpa.QueryImpl.performPreQueryFlush(QueryImpl.java:963)
> at org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:207)
> at org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:469)
> at org.apache.ranger.db.XXPolicyResourceMapDao.findByPolicyId(XXPolicyResourceMapDao.java:56)
> at org.apache.ranger.biz.RangerPolicyRetriever$RetrieverContext.<init>(RangerPolicyRetriever.java:552)
> at org.apache.ranger.biz.RangerPolicyRetriever$RetrieverContext.getAllPoliciesBySecondary(RangerPolicyRetriever.java:671)
> {code}
> * Many such request logs
> spark app run
> {code:java}
> 10.12.11.16 - - [11/Nov/2021:17:12:28 +0800] "GET /service/plugins/secure/policies/download/spark_offline?lastKnownVersion=29397&lastActivationTime=1636621258729&pluginId=sparkSql%40fs-hiido-dn-12-11-16.hiido.host.yydevops.com-spark_offline&clusterName= HTTP/1.1" 304 - "-" "Java/1.8.0_201" {code}
> practical
> {code:java}
> {{ { "configs": \{ "jdbc.driverClassName": "org.apache.hive.jdbc.HiveDriver", "jdbc.url": "jdbc:hive2://10.21.112.3:30000", "password": "*****", "policy.download.auth.users": "*", "policy.grantrevoke.auth.users": "*", "tag.download.auth.users": "*", "username": "hdfs" }
> , "createTime": 1573165348000, "createdBy": "Admin", "description": "spark_offline cluster", "guid": "ddb5305b-d145-44f7-af09-77b41d28959f", "id": 17, "isEnabled": true, "name": "spark_offline", "policyUpdateTime": 1636621544000, "policyVersion": 29412, "tagUpdateTime": 1573194148000, "tagVersion": 1, "type": "hive", "updateTime": 1573432854000, "updatedBy": "Admin", "version": 13 },}}
> {code}
> lastKnownVersion=29397 >policyVersion": 29412 ?? When does this happen
> After the ranger service is restarted, the ranger service is restored
> The request log becomes lastKnownVersion=29412
> lastKnownVersion Where did you get it from? Is the cache not flushed yet?
> ` boolean getLatestOrCached(String serviceName, ServiceStore serviceStore) throws Exception {
> boolean ret = false;
> {code:java}
> //
> try {
> ret = lock.tryLock(waitTimeInSeconds, TimeUnit.SECONDS);
> if (ret) {
> getLatest(serviceName, serviceStore);
> }
> } catch (InterruptedException exception) {
> LOG.error("getLatestOrCached:lock got interrupted..", exception);
> } finally {
> if (ret) {
> lock.unlock();
> }
> }
> return ret;
> } {code}
>
>
> * This is the full JStack in question
> [^ranger_1_1115.jstack]
--
This message was sent by Atlassian Jira
(v8.20.1#820001)