You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@ranger.apache.org by ma...@apache.org on 2016/03/20 19:30:08 UTC

[5/8] incubator-ranger git commit: RANGER-794: commit id f79bc59a0b4756ca5195a2ffb30759b4a82175ef

RANGER-794: commit id f79bc59a0b4756ca5195a2ffb30759b4a82175ef

Signed-off-by: Madhan Neethiraj <ma...@apache.org>


Project: http://git-wip-us.apache.org/repos/asf/incubator-ranger/repo
Commit: http://git-wip-us.apache.org/repos/asf/incubator-ranger/commit/bec2fefe
Tree: http://git-wip-us.apache.org/repos/asf/incubator-ranger/tree/bec2fefe
Diff: http://git-wip-us.apache.org/repos/asf/incubator-ranger/diff/bec2fefe

Branch: refs/heads/ranger-0.5
Commit: bec2fefe1b0101a2be17e57ab3ecfeeb91837bde
Parents: e72cb20
Author: Abhay Kulkarni <ak...@hortonworks.com>
Authored: Wed Jan 13 11:56:04 2016 -0800
Committer: Madhan Neethiraj <ma...@apache.org>
Committed: Sun Mar 20 10:34:39 2016 -0700

----------------------------------------------------------------------
 .../policyengine/RangerPolicyEngineImpl.java    | 61 +++++++++++++++++-
 .../policyengine/RangerPolicyRepository.java    | 12 ++++
 .../RangerCachedPolicyEvaluator.java            |  2 +-
 .../RangerDefaultPolicyEvaluator.java           | 65 ++++++++++++++++----
 .../RangerDefaultPolicyItemEvaluator.java       | 50 ++++++++++++++-
 .../ranger/plugin/util/PolicyRefresher.java     | 12 +++-
 .../ranger/plugin/util/RangerPerfTracer.java    |  9 ++-
 ranger-tools/conf/log4j.properties              |  4 +-
 .../src/test/resources/log4j.properties         |  4 +-
 ranger-tools/testdata/test_modules.txt          | 18 +++++-
 10 files changed, 210 insertions(+), 27 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java
index d2b3a5c..c276d5a 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java
@@ -27,6 +27,7 @@ import org.apache.ranger.plugin.model.RangerPolicy;
 import org.apache.ranger.plugin.model.RangerServiceDef;
 import org.apache.ranger.plugin.model.RangerPolicy.RangerPolicyResource;
 import org.apache.ranger.plugin.policyevaluator.RangerPolicyEvaluator;
+import org.apache.ranger.plugin.util.RangerPerfTracer;
 import org.apache.ranger.plugin.util.ServicePolicies;
 
 import java.util.ArrayList;
@@ -39,6 +40,11 @@ import java.util.Set;
 public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 	private static final Log LOG = LogFactory.getLog(RangerPolicyEngineImpl.class);
 
+	private static final Log PERF_POLICYENGINE_INIT_LOG = RangerPerfTracer.getPerfLogger("policyengine.init");
+	private static final Log PERF_POLICYENGINE_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policyengine.request");
+	private static final Log PERF_POLICYENGINE_AUDIT_LOG = RangerPerfTracer.getPerfLogger("policyengine.audit");
+	private static final Log PERF_CONTEXTENRICHER_REQUEST_LOG = RangerPerfTracer.getPerfLogger("contextenricher.request");
+
 	private final RangerPolicyRepository policyRepository;
 
 
@@ -51,12 +57,20 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			LOG.debug("==> RangerPolicyEngineImpl(" + servicePolicies + ", " + options + ")");
 		}
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_INIT_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_INIT_LOG, "RangerPolicyEngine.init(hashCode=" + Integer.toHexString(System.identityHashCode(this)) + ")");
+		}
+
 		if(options == null) {
 			options = new RangerPolicyEngineOptions();
 		}
 
 		policyRepository = new RangerPolicyRepository(servicePolicies, options);
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerPolicyEngineImpl()");
 		}
@@ -93,9 +107,20 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 		List<RangerContextEnricher> enrichers = policyRepository.getContextEnrichers();
 
 		if(!CollectionUtils.isEmpty(enrichers)) {
+
 			for(RangerContextEnricher enricher : enrichers) {
+
+				RangerPerfTracer perf = null;
+
+				if(RangerPerfTracer.isPerfTraceEnabled(PERF_CONTEXTENRICHER_REQUEST_LOG)) {
+					perf = RangerPerfTracer.getPerfTracer(PERF_CONTEXTENRICHER_REQUEST_LOG, "RangerContextEnricher.enrich(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ")");
+				}
+
 				enricher.enrich(request);
+
+				RangerPerfTracer.log(perf);
 			}
+
 		}
 
 		if(LOG.isDebugEnabled()) {
@@ -136,12 +161,28 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			LOG.debug("==> RangerPolicyEngineImpl.isAccessAllowed(" + request + ")");
 		}
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_REQUEST_LOG, "RangerPolicyEngine.isAccessAllowed(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ")");
+		}
+
 		RangerAccessResult ret = isAccessAllowedNoAudit(request);
 
-		if(resultProcessor != null) {
+		if (resultProcessor != null) {
+
+			RangerPerfTracer perfAuditTracer = null;
+			if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_AUDIT_LOG)) {
+				perfAuditTracer = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_AUDIT_LOG, "RangerPolicyEngine.processAudit(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ")");
+			}
+
 			resultProcessor.processResult(ret);
+
+			RangerPerfTracer.log(perfAuditTracer);
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowed(" + request + "): " + ret);
 		}
@@ -182,6 +223,11 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			LOG.debug("==> RangerPolicyEngineImpl.isAccessAllowed(" + resource + ", " + user + ", " + userGroups + ", " + accessType + ")");
 		}
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_REQUEST_LOG, "RangerPolicyEngine.isAccessAllowed(user=" + user + ",accessType=" + accessType + "resource=" + resource.getAsString() + ")");
+		}
 		boolean ret = false;
 
 		for(RangerPolicyEvaluator evaluator : policyRepository.getPolicyEvaluators()) {
@@ -192,6 +238,8 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			}
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowed(" + resource + ", " + user + ", " + userGroups + ", " + accessType + "): " + ret);
 		}
@@ -206,6 +254,11 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			LOG.debug("==> RangerPolicyEngineImpl.isAccessAllowed(" + resources + ", " + user + ", " + userGroups + ", " + accessType + ")");
 		}
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_REQUEST_LOG, "RangerPolicyEngine.isAccessAllowed(user=" + user + ",accessType=" + accessType + ")");
+		}
 		boolean ret = false;
 
 		for(RangerPolicyEvaluator evaluator : policyRepository.getPolicyEvaluators()) {
@@ -216,7 +269,9 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			}
 		}
 
-		if(LOG.isDebugEnabled()) {
+		RangerPerfTracer.log(perf);
+
+		if (LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowed(" + resources + ", " + user + ", " + userGroups + ", " + accessType + "): " + ret);
 		}
 
@@ -300,7 +355,7 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine {
 			}
 		}
 
-		if(LOG.isDebugEnabled()) {
+		if (LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowedNoAudit(" + request + "): " + ret);
 		}
 

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java
index 45bc792..1f422c5 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java
@@ -31,6 +31,7 @@ import org.apache.ranger.plugin.policyevaluator.RangerCachedPolicyEvaluator;
 import org.apache.ranger.plugin.policyevaluator.RangerDefaultPolicyEvaluator;
 import org.apache.ranger.plugin.policyevaluator.RangerOptimizedPolicyEvaluator;
 import org.apache.ranger.plugin.policyevaluator.RangerPolicyEvaluator;
+import org.apache.ranger.plugin.util.RangerPerfTracer;
 import org.apache.ranger.plugin.util.ServicePolicies;
 
 import java.util.ArrayList;
@@ -42,6 +43,8 @@ import java.util.Map;
 public class RangerPolicyRepository {
     private static final Log LOG = LogFactory.getLog(RangerPolicyRepository.class);
 
+    private static final Log PERF_CONTEXTENRICHER_INIT_LOG = RangerPerfTracer.getPerfLogger("contextenricher.init");
+
     private final String                      serviceName;
     private final RangerServiceDef            serviceDef;
     private final List<RangerPolicy>          policies;
@@ -84,6 +87,7 @@ public class RangerPolicyRepository {
 
             RangerPolicyEvaluator evaluator = buildPolicyEvaluator(policy, serviceDef, options);
 
+
             if (evaluator != null) {
                 policyEvaluators.add(evaluator);
             }
@@ -133,6 +137,12 @@ public class RangerPolicyRepository {
 
         RangerContextEnricher ret = null;
 
+        RangerPerfTracer perf = null;
+
+        if(RangerPerfTracer.isPerfTraceEnabled(PERF_CONTEXTENRICHER_INIT_LOG)) {
+            perf = RangerPerfTracer.getPerfTracer(PERF_CONTEXTENRICHER_INIT_LOG, "RangerContextEnricher.init(name=" + enricherDef.getName() + ")");
+        }
+
         String name    = enricherDef != null ? enricherDef.getName()     : null;
         String clsName = enricherDef != null ? enricherDef.getEnricher() : null;
 
@@ -152,6 +162,8 @@ public class RangerPolicyRepository {
             ret.init();
         }
 
+        RangerPerfTracer.log(perf);
+
         if(LOG.isDebugEnabled()) {
             LOG.debug("<== RangerPolicyRepository.buildContextEnricher(" + enricherDef + "): " + ret);
         }

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java
index d67777c..91a53d8 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java
@@ -40,7 +40,7 @@ public class RangerCachedPolicyEvaluator extends RangerOptimizedPolicyEvaluator
         super.init(policy, serviceDef, options);
 
         cache = RangerResourceAccessCacheImpl.getInstance(serviceDef, policy);
-        
+
         if(LOG.isDebugEnabled()) {
             LOG.debug("<== RangerCachedPolicyEvaluator.init()");
         }

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java
index 9f60b7b..d570c6c 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java
@@ -44,14 +44,19 @@ import org.apache.ranger.plugin.policyengine.RangerAccessResult;
 import org.apache.ranger.plugin.policyengine.RangerPolicyEngineOptions;
 import org.apache.ranger.plugin.policyresourcematcher.RangerDefaultPolicyResourceMatcher;
 import org.apache.ranger.plugin.policyresourcematcher.RangerPolicyResourceMatcher;
+import org.apache.ranger.plugin.util.RangerPerfTracer;
 
 
 public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator {
 	private static final Log LOG = LogFactory.getLog(RangerDefaultPolicyEvaluator.class);
 
+	private static final Log PERF_POLICY_INIT_LOG = RangerPerfTracer.getPerfLogger("policy.init");
+	private static final Log PERF_POLICY_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policy.request");
+
 	private RangerPolicyResourceMatcher     resourceMatcher       = null;
 	private List<RangerPolicyItemEvaluator> policyItemEvaluators  = null;
 	private int                             customConditionsCount = 0;
+	private String perfTag;
 
 	@Override
 	public int getCustomConditionsCount() {
@@ -65,6 +70,18 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
 		}
 
 		preprocessPolicy(policy, serviceDef);
+		StringBuffer perfTagBuffer = new StringBuffer();
+		if (policy != null) {
+			perfTagBuffer.append("policyId=").append(policy.getId()).append(", policyName=").append(policy.getName());
+		}
+
+		perfTag = perfTagBuffer.toString();
+
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_INIT_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_INIT_LOG, "RangerPolicyEvaluator.init(" + perfTag + ")");
+		}
 
 		super.init(policy, serviceDef, options);
 
@@ -92,6 +109,8 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
 			policyItemEvaluators = Collections.<RangerPolicyItemEvaluator>emptyList();
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerDefaultPolicyEvaluator.init()");
 		}
@@ -103,6 +122,13 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
             LOG.debug("==> RangerDefaultPolicyEvaluator.evaluate(" + request + ", " + result + ")");
         }
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_REQUEST_LOG, "RangerPolicyEvaluator.evaluate(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ","
+					+ perfTag + ")");
+		}
+
         if (request != null && result != null) {
             boolean isMatchAttempted     = false;
             boolean matchResult          = false;
@@ -147,18 +173,21 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
                         headMatchResult = matchResourceHead(request.getResource());
 	                    isHeadMatchAttempted = true;
                     }
-                }
-                // Go further to evaluate access only if match or head match was found at this point
-                if (matchResult || headMatchResult) {
-                    evaluatePolicyItemsForAccess(request, result);
-                }
-            }
-        }
+				}
+				// Go further to evaluate access only if match or head match was found at this point
+				if (matchResult || headMatchResult) {
+					evaluatePolicyItemsForAccess(request, result);
+				}
+			}
+		}
 
-        if(LOG.isDebugEnabled()) {
+		RangerPerfTracer.log(perf);
+
+		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerDefaultPolicyEvaluator.evaluate(" + request + ", " + result + ")");
 		}
-	}
+
+    }
 
     protected void evaluatePolicyItemsForAccess(RangerAccessRequest request, RangerAccessResult result) {
         if(LOG.isDebugEnabled()) {
@@ -188,10 +217,18 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
 
 		boolean ret = false;
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_REQUEST_LOG, "RangerPolicyEvaluator.isMatch(resource=" + resource.getAsString() + "," + perfTag + ")");
+		}
+
 		if(resourceMatcher != null) {
 			ret = resourceMatcher.isMatch(resource);
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerDefaultPolicyEvaluator.isMatch(" + resource + "): " + ret);
 		}
@@ -292,6 +329,11 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
 
 		boolean ret = false;
 
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_REQUEST_LOG, "RangerPolicyEvaluator.isAccessAllowed(hashCode=" + Integer.toHexString(System.identityHashCode(this)) + "," + perfTag + ")");
+		}
 		if(CollectionUtils.isNotEmpty(policyItemEvaluators)) {
 	        for (RangerPolicyItemEvaluator policyItemEvaluator : policyItemEvaluators) {
 	        	ret = policyItemEvaluator.matchUserGroup(user, userGroups) &&
@@ -303,6 +345,8 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
 	        }
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerDefaultPolicyEvaluator.isAccessAllowed(" + user + ", " + userGroups + ", " + accessType + "): " + ret);
 		}
@@ -415,6 +459,3 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator
 		return ret;
 	}
 }
-
-
-

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java
index bf9b243..e8d90fa 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java
@@ -37,11 +37,16 @@ import org.apache.ranger.plugin.policyengine.RangerAccessRequest;
 import org.apache.ranger.plugin.policyengine.RangerAccessResult;
 import org.apache.ranger.plugin.policyengine.RangerPolicyEngine;
 import org.apache.ranger.plugin.policyengine.RangerPolicyEngineOptions;
+import org.apache.ranger.plugin.util.RangerPerfTracer;
 
 
 public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEvaluator {
 	private static final Log LOG = LogFactory.getLog(RangerDefaultPolicyItemEvaluator.class);
 
+	private static final Log PERF_POLICYITEM_INIT_LOG = RangerPerfTracer.getPerfLogger("policyitem.init");
+	private static final Log PERF_POLICYITEM_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policyitem.request");
+	private static final Log PERF_POLICYCONDITION_INIT_LOG = RangerPerfTracer.getPerfLogger("policycondition.init");
+	private static final Log PERF_POLICYCONDITION_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policycondition.request");
 
 	public RangerDefaultPolicyItemEvaluator(RangerServiceDef serviceDef, RangerPolicy policy, RangerPolicyItem policyItem, RangerPolicyEngineOptions options) {
 		super(serviceDef, policy, policyItem, options);
@@ -55,6 +60,12 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv
 		if (!getConditionsDisabledOption() && policyItem != null && CollectionUtils.isNotEmpty(policyItem.getConditions())) {
 			conditionEvaluators = new ArrayList<RangerConditionEvaluator>();
 
+			RangerPerfTracer perf = null;
+
+			if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYITEM_INIT_LOG)) {
+				perf = RangerPerfTracer.getPerfTracer(PERF_POLICYITEM_INIT_LOG, "RangerPolicyItemEvaluator.init(policyId=" + policyId + ")");
+			}
+
 			for (RangerPolicyItemCondition condition : policyItem.getConditions()) {
 				RangerPolicyConditionDef conditionDef = getConditionDef(condition.getType());
 
@@ -69,13 +80,23 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv
 				if (conditionEvaluator != null) {
 					conditionEvaluator.setConditionDef(conditionDef);
 					conditionEvaluator.setPolicyItemCondition(condition);
+
+					RangerPerfTracer perfConditionInit = null;
+
+					if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYCONDITION_INIT_LOG)) {
+						perfConditionInit = RangerPerfTracer.getPerfTracer(PERF_POLICYCONDITION_INIT_LOG, "RangerConditionEvaluator.init(policyId=" + policyId + ",policyConditionType=" + condition.getType() + ")");
+					}
+
 					conditionEvaluator.init();
 
+					RangerPerfTracer.log(perfConditionInit);
+
 					conditionEvaluators.add(conditionEvaluator);
 				} else {
 					LOG.error("RangerDefaultPolicyItemEvaluator(policyId=" + policyId + "): failed to instantiate condition evaluator '" + condition.getType() + "'; evaluatorClassName='" + conditionDef.getEvaluator() + "'");
 				}
 			}
+			RangerPerfTracer.log(perf);
 		}
 
 		if(LOG.isDebugEnabled()) {
@@ -89,6 +110,14 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv
 			LOG.debug("==> RangerDefaultPolicyItemEvaluator.evaluate(" + request + ", " + result + ")");
 		}
 
+		boolean ret = false;
+
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYITEM_REQUEST_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICYITEM_REQUEST_LOG, "RangerPolicyItemEvaluator.isMatch(resource=" + request.getResource().getAsString()  + ")");
+		}
+
 		if(policyItem != null) {
 			if(matchUserGroup(request.getUser(), request.getUserGroups())) {
 				if (request.isAccessTypeDelegatedAdmin()) { // used only in grant/revoke scenario
@@ -125,6 +154,8 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv
 			}
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if(LOG.isDebugEnabled()) {
 			LOG.debug("<== RangerDefaultPolicyItemEvaluator.evaluate(" + request + ", " + result + ")");
 		}
@@ -209,7 +240,24 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv
 
 		if (CollectionUtils.isNotEmpty(conditionEvaluators)) {
 			for(RangerConditionEvaluator conditionEvaluator : conditionEvaluators) {
-				if(!conditionEvaluator.isMatched(request)) {
+				if(LOG.isDebugEnabled()) {
+					LOG.debug("evaluating condition: " + conditionEvaluator);
+				}
+				RangerPerfTracer perf = null;
+
+				if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYCONDITION_REQUEST_LOG)) {
+					perf = RangerPerfTracer.getPerfTracer(PERF_POLICYCONDITION_REQUEST_LOG, "RangerConditionEvaluator.matchCondition(policyId=" + policyId + ")");
+				}
+
+				boolean conditionEvalResult = conditionEvaluator.isMatched(request);
+
+				RangerPerfTracer.log(perf);
+
+				if (!conditionEvalResult) {
+					if(LOG.isDebugEnabled()) {
+						LOG.debug(conditionEvaluator + " returned false");
+					}
+
 					ret = false;
 
 					break;

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java b/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java
index 0729339..27968eb 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java
@@ -38,6 +38,8 @@ import com.google.gson.GsonBuilder;
 public class PolicyRefresher extends Thread {
 	private static final Log LOG = LogFactory.getLog(PolicyRefresher.class);
 
+	private static final Log PERF_POLICYENGINE_INIT_LOG = RangerPerfTracer.getPerfLogger("policyengine.init");
+
 	private final RangerBasePlugin  plugIn;
 	private final String            serviceType;
 	private final String            serviceName;
@@ -171,7 +173,13 @@ public class PolicyRefresher extends Thread {
 			LOG.debug("==> PolicyRefresher(serviceName=" + serviceName + ").loadPolicy()");
 		}
 
-		//load policy from PolicyAmdin
+		RangerPerfTracer perf = null;
+
+		if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_INIT_LOG)) {
+			perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_INIT_LOG, "PolicyRefresher.loadPolicy(serviceName=" + serviceName + ")");
+		}
+
+		//load policy from PolicyAdmin
 		ServicePolicies svcPolicies = loadPolicyfromPolicyAdmin();
 
 		if ( svcPolicies == null) {
@@ -183,6 +191,8 @@ public class PolicyRefresher extends Thread {
 			saveToCache(svcPolicies);
 		}
 
+		RangerPerfTracer.log(perf);
+
 		if (svcPolicies != null) {
 			plugIn.setPolicies(svcPolicies);
 			policiesSetInPlugin = true;

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
----------------------------------------------------------------------
diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
index 175c4e4..e130cc7 100644
--- a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
+++ b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
@@ -29,10 +29,12 @@ public class RangerPerfTracer {
 	protected final String data;
 	private final long   startTimeMs;
 
+	private static long reportingThresholdMs = 0L;
+
 	private final static String tagEndMarker = "(";
 
 	public static Log getPerfLogger(String name) {
-		return LogFactory.getLog("ranger.perf." + name);
+		return LogFactory.getLog("org.apache.ranger.perf." + name);
 	}
 
 	public static Log getPerfLogger(Class<?> cls) {
@@ -89,8 +91,9 @@ public class RangerPerfTracer {
 	}
 
 	public void log() {
-		if(logger.isDebugEnabled()) {
-			logger.debug("[PERF] " + tag + data + ": " + getElapsedTime());
+		long elapsedTime = getElapsedTime();
+		if (elapsedTime > reportingThresholdMs) {
+			logger.debug("[PERF] " + tag + data + ": " + elapsedTime);
 		}
 	}
 }

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/ranger-tools/conf/log4j.properties
----------------------------------------------------------------------
diff --git a/ranger-tools/conf/log4j.properties b/ranger-tools/conf/log4j.properties
index ccb9db4..86f5c18 100644
--- a/ranger-tools/conf/log4j.properties
+++ b/ranger-tools/conf/log4j.properties
@@ -40,8 +40,8 @@ log4j.appender.console.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c{2}: %L
 ranger.perf.logger=DEBUG,PERF
 ranger.perf.log.file=ranger-perf-test.log
 
-log4j.logger.ranger.perf=${ranger.perf.logger}
-log4j.additivity.ranger.perf=false
+log4j.logger.org.apache.ranger.perf=${ranger.perf.logger}
+log4j.additivity.org.apache.ranger.perf=false
 
 log4j.appender.PERF=org.apache.log4j.DailyRollingFileAppender
 log4j.appender.PERF.File=${ranger.perf.log.file}

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/ranger-tools/src/test/resources/log4j.properties
----------------------------------------------------------------------
diff --git a/ranger-tools/src/test/resources/log4j.properties b/ranger-tools/src/test/resources/log4j.properties
index abf617e..4ea9d85 100644
--- a/ranger-tools/src/test/resources/log4j.properties
+++ b/ranger-tools/src/test/resources/log4j.properties
@@ -40,8 +40,8 @@ log4j.appender.console.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c{2}: %L
 ranger.perf.logger=DEBUG,PERF
 ranger.perf.log.file=${java.io.tmpdir}/ranger-perf-test.log
 
-log4j.logger.ranger.perf=${ranger.perf.logger}
-log4j.additivity.ranger.perf=false
+log4j.logger.org.apache.ranger.perf=${ranger.perf.logger}
+log4j.additivity.org.apache.ranger.perf=false
 
 log4j.appender.PERF=org.apache.log4j.DailyRollingFileAppender
 log4j.appender.PERF.File=${ranger.perf.log.file}

http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/ranger-tools/testdata/test_modules.txt
----------------------------------------------------------------------
diff --git a/ranger-tools/testdata/test_modules.txt b/ranger-tools/testdata/test_modules.txt
index 33432ed..9ffcbfc 100644
--- a/ranger-tools/testdata/test_modules.txt
+++ b/ranger-tools/testdata/test_modules.txt
@@ -17,6 +17,20 @@
 # under the License.
 #
 
+PolicyRefresher.loadPolicy
 RangerPolicyEngine.init
-RangerPolicyEngine.preProcess
-RangerPolicyEngine.isAccessAllowedNoAudit
+RangerContextEnricher.init
+RangerPolicyEvaluator.init
+RangerPolicyItemEvaluator.init
+RangerConditionEvaluator.init
+RangerContextEnricher.enrich
+RangerPolicyEngine.isAccessAllowed
+RangerPolicyEvaluator.evaluate
+RangerPolicyEvaluator.isMatch
+RangerPolicyItemEvaluator.isMatch
+RangerConditionEvaluator.matchCondition
+RangerPolicyEngine.processAudit
+RangerTagRefresher.populateTags
+RangerPolicyEvaluator.isAccessAllowed
+RangerPolicyRetriever.getServicePolicies
+RangerTagDBReceiver.getTags