| /* |
| * Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved. |
| * |
| * This program and the accompanying materials are made available under the |
| * terms of the Eclipse Public License v. 2.0 which is available at |
| * http://www.eclipse.org/legal/epl-2.0, |
| * or the Eclipse Distribution License v. 1.0 which is available at |
| * http://www.eclipse.org/org/documents/edl-v10.php. |
| * |
| * SPDX-License-Identifier: EPL-2.0 OR BSD-3-Clause |
| */ |
| |
| // Contributors: |
| // Oracle - initial API and implementation from Oracle TopLink |
| package org.eclipse.persistence.tools.profiler; |
| |
| import java.io.IOException; |
| import java.io.Serializable; |
| import java.io.Writer; |
| import java.util.Collection; |
| import java.util.Enumeration; |
| import java.util.Hashtable; |
| import java.util.List; |
| import java.util.Map; |
| import java.util.Vector; |
| |
| import org.eclipse.persistence.internal.helper.Helper; |
| import org.eclipse.persistence.internal.localization.ToStringLocalization; |
| import org.eclipse.persistence.internal.sessions.AbstractRecord; |
| import org.eclipse.persistence.internal.sessions.AbstractSession; |
| import org.eclipse.persistence.queries.DatabaseQuery; |
| import org.eclipse.persistence.sessions.DataRecord; |
| import org.eclipse.persistence.sessions.SessionProfilerAdapter; |
| |
| /** |
| * <p><b>Purpose</b>: A tool used to provide high level performance profiling information. |
| * |
| * @since TopLink 1.0 |
| * @author James Sutherland |
| */ |
| public class PerformanceProfiler extends SessionProfilerAdapter implements Serializable, Cloneable { |
| protected List<Profile> profiles; |
| transient protected AbstractSession session; |
| protected boolean shouldLogProfile; |
| protected int nestLevel; |
| protected long nestTime; |
| protected long profileTime; |
| protected Map<Integer, Map<String, Long>> operationTimingsByThread;//facilitates concurrency |
| protected Map<Integer, Map<String, Long>> operationStartTimesByThread;//facilitates concurrency |
| |
| /** |
| * PUBLIC: |
| * Create a new profiler. |
| * The profiler can be registered with a session to log performance information on queries. |
| */ |
| public PerformanceProfiler() { |
| this(true); |
| } |
| |
| /** |
| * PUBLIC: |
| * Create a new profiler. |
| * The profiler can be registered with a session to log performance information on queries. |
| */ |
| public PerformanceProfiler(boolean shouldLogProfile) { |
| super(); |
| this.profiles = new Vector<>(); |
| this.shouldLogProfile = shouldLogProfile; |
| this.nestLevel = 0; |
| this.profileTime = 0; |
| this.nestTime = 0; |
| this.operationTimingsByThread = new Hashtable<>(); |
| this.operationStartTimesByThread = new Hashtable<>(); |
| } |
| |
| protected void addProfile(Profile profile) { |
| getProfiles().add(profile); |
| } |
| |
| /** |
| * INTERNAL: |
| * Return a summary profile reporting on the profiles contained. |
| */ |
| public Profile buildProfileSummary() { |
| Profile summary = new Profile(); |
| summary.setDomainClass(Void.class); |
| summary.setQueryClass(Void.class); |
| for (Profile profile : getProfiles()) { |
| if ((summary.getShortestTime() == -1) || (profile.getTotalTime() < summary.getShortestTime())) { |
| summary.setShortestTime(profile.getTotalTime()); |
| } |
| if (profile.getTotalTime() > summary.getLongestTime()) { |
| summary.setLongestTime(profile.getTotalTime()); |
| } |
| summary.setTotalTime(summary.getTotalTime() + profile.getTotalTime()); |
| summary.setLocalTime(summary.getLocalTime() + profile.getLocalTime()); |
| summary.setProfileTime(summary.getProfileTime() + profile.getProfileTime()); |
| summary.setNumberOfInstancesEffected(summary.getNumberOfInstancesEffected() + profile.getNumberOfInstancesEffected()); |
| for (Map.Entry<String, Long> entry: profile.getOperationTimings().entrySet()) { |
| String name = entry.getKey(); |
| Long oldTime = summary.getOperationTimings().get(name); |
| long profileTime = entry.getValue(); |
| long newTime; |
| if (oldTime == null) { |
| newTime = profileTime; |
| } else { |
| newTime = oldTime + profileTime; |
| } |
| summary.getOperationTimings().put(name, newTime); |
| } |
| } |
| |
| return summary; |
| } |
| |
| /** |
| * INTERNAL: |
| * Return a map of summary profiles reporting on the profile contained. |
| */ |
| public Hashtable<Class<?>, Profile> buildProfileSummaryByClass() { |
| Hashtable<Class<?>, Profile> summaries = new Hashtable<>(); |
| |
| for (Profile profile : getProfiles()) { |
| Class<?> domainClass = profile.getDomainClass(); |
| if (domainClass == null) { |
| domainClass = Void.class; |
| } |
| |
| Profile summary = summaries.get(domainClass); |
| if (summary == null) { |
| summary = new Profile(); |
| summary.setDomainClass(domainClass); |
| summaries.put(domainClass, summary); |
| } |
| if ((summary.getShortestTime() == -1) || (profile.getTotalTime() < summary.getShortestTime())) { |
| summary.setShortestTime(profile.getTotalTime()); |
| } |
| if (profile.getTotalTime() > summary.getLongestTime()) { |
| summary.setLongestTime(profile.getTotalTime()); |
| } |
| summary.setTotalTime(summary.getTotalTime() + profile.getTotalTime()); |
| summary.setLocalTime(summary.getLocalTime() + profile.getLocalTime()); |
| summary.setProfileTime(summary.getProfileTime() + profile.getProfileTime()); |
| summary.setNumberOfInstancesEffected(summary.getNumberOfInstancesEffected() + profile.getNumberOfInstancesEffected()); |
| for (Map.Entry<String, Long> entry: profile.getOperationTimings().entrySet()) { |
| String name = entry.getKey(); |
| Long oldTime = summary.getOperationTimings().get(name); |
| long profileTime = entry.getValue(); |
| long newTime; |
| if (oldTime == null) { |
| newTime = profileTime; |
| } else { |
| newTime = oldTime + profileTime; |
| } |
| summary.getOperationTimings().put(name, newTime); |
| } |
| } |
| |
| return summaries; |
| } |
| |
| /** |
| * INTERNAL: |
| * Return a map of summary profiles reporting on the profile contained. |
| */ |
| public Hashtable<Class<?>, Profile> buildProfileSummaryByQuery() { |
| Hashtable<Class<?>, Profile> summaries = new Hashtable<>(); |
| |
| for (Profile profile : getProfiles()) { |
| Class<?> queryType = profile.getQueryClass(); |
| if (queryType == null) { |
| queryType = Void.class; |
| } |
| |
| Profile summary = summaries.get(queryType); |
| if (summary == null) { |
| summary = new Profile(); |
| summary.setQueryClass(queryType); |
| summaries.put(queryType, summary); |
| } |
| summary.setTotalTime(summary.getTotalTime() + profile.getTotalTime()); |
| summary.setLocalTime(summary.getLocalTime() + profile.getLocalTime()); |
| summary.setProfileTime(summary.getProfileTime() + profile.getProfileTime()); |
| summary.setNumberOfInstancesEffected(summary.getNumberOfInstancesEffected() + profile.getNumberOfInstancesEffected()); |
| for (Map.Entry<String, Long> entry: profile.getOperationTimings().entrySet()) { |
| String name = entry.getKey(); |
| Long oldTime = summary.getOperationTimings().get(name); |
| long profileTime = entry.getValue(); |
| long newTime; |
| if (oldTime == null) { |
| newTime = profileTime; |
| } else { |
| newTime = oldTime + profileTime; |
| } |
| summary.getOperationTimings().put(name, newTime); |
| } |
| } |
| |
| return summaries; |
| } |
| |
| @Override |
| public PerformanceProfiler clone() { |
| try { |
| return (PerformanceProfiler)super.clone(); |
| } catch (CloneNotSupportedException exception) { |
| throw new InternalError(); |
| } |
| } |
| |
| /** |
| * PUBLIC: |
| * Set whether after each query execution the profile result should be logged. |
| * By default this is false. |
| */ |
| public void dontLogProfile() { |
| setShouldLogProfile(false); |
| } |
| |
| /** |
| * INTERNAL: |
| * End the operation timing. |
| */ |
| @Override |
| public void endOperationProfile(String operationName) { |
| long endTime = System.nanoTime(); |
| Long startTime = getOperationStartTimes().get(operationName); |
| if (startTime == null) { |
| return; |
| } |
| long time = endTime - startTime; |
| |
| if (getNestLevel() == 0) { |
| // Log as a profile if not within query execution, |
| // unless no time was recorded, in which case discard. |
| if (time == 0) { |
| return; |
| } |
| Profile profile = new Profile(); |
| profile.setTotalTime(time); |
| profile.setLocalTime(time); |
| profile.addTiming(operationName, time); |
| addProfile(profile); |
| if (shouldLogProfile()) { |
| Writer writer = getSession().getLog(); |
| try { |
| profile.write(writer, this); |
| writer.write(Helper.cr()); |
| writer.flush(); |
| } catch (IOException ioe) { |
| } |
| } |
| } |
| |
| Long totalTime = getOperationTimings().get(operationName); |
| if (totalTime == null) { |
| getOperationTimings().put(operationName, time); |
| } else { |
| getOperationTimings().put(operationName, totalTime + time); |
| } |
| } |
| |
| /** |
| * INTERNAL: |
| * End the operation timing. |
| */ |
| @Override |
| public void endOperationProfile(String operationName, DatabaseQuery query, int weight) { |
| endOperationProfile(operationName); |
| } |
| |
| protected int getNestLevel() { |
| return nestLevel; |
| } |
| |
| protected long getNestTime() { |
| return nestTime; |
| } |
| |
| protected Map<String, Long> getOperationStartTimes() { |
| Integer threadId = Thread.currentThread().hashCode(); |
| if (getOperationStartTimesByThread().get(threadId) == null) { |
| getOperationStartTimesByThread().put(threadId, new Hashtable<>(10)); |
| } |
| return getOperationStartTimesByThread().get(threadId); |
| } |
| |
| protected Map<Integer, Map<String, Long>> getOperationStartTimesByThread() { |
| return operationStartTimesByThread; |
| } |
| |
| protected Map<String, Long> getOperationTimings() { |
| Integer threadId = Thread.currentThread().hashCode(); |
| if (getOperationTimingsByThread().get(threadId) == null) { |
| getOperationTimingsByThread().put(threadId, new Hashtable<>(10)); |
| } |
| return getOperationTimingsByThread().get(threadId); |
| } |
| |
| protected Map<Integer, Map<String, Long>> getOperationTimingsByThread() { |
| return operationTimingsByThread; |
| } |
| |
| /** |
| * Return the profiles logged in this profiler. |
| */ |
| public List<Profile> getProfiles() { |
| return profiles; |
| } |
| |
| protected long getProfileTime() { |
| return profileTime; |
| } |
| |
| public AbstractSession getSession() { |
| return session; |
| } |
| |
| /** |
| * PUBLIC: |
| * Set whether after each query execution the profile result should be logged. |
| * By default this is true. |
| */ |
| public void logProfile() { |
| setShouldLogProfile(true); |
| } |
| |
| /** |
| * PUBLIC: |
| * Log a profile summary. |
| */ |
| public void logProfileSummary() { |
| Writer writer = getSession().getLog(); |
| try { |
| writer.write(buildProfileSummary().toString()); |
| writer.write(Helper.cr()); |
| } catch (IOException ioe) { |
| } |
| } |
| |
| /** |
| * PUBLIC: |
| * Log a profile summary by class. |
| */ |
| public void logProfileSummaryByClass() { |
| Hashtable<Class<?>, Profile> summaries = buildProfileSummaryByClass(); |
| |
| for (Enumeration<Class<?>> classes = summaries.keys(); classes.hasMoreElements();) { |
| Class<?> domainClass = classes.nextElement(); |
| Writer writer = getSession().getLog(); |
| try { |
| writer.write(summaries.get(domainClass).toString()); |
| writer.write(Helper.cr()); |
| } catch (IOException ioe) { |
| } |
| } |
| } |
| |
| /** |
| * PUBLIC: |
| * Log a profile summary by query. |
| */ |
| public void logProfileSummaryByQuery() { |
| Hashtable<Class<?>, Profile> summaries = buildProfileSummaryByQuery(); |
| |
| for (Enumeration<Class<?>> classes = summaries.keys(); classes.hasMoreElements();) { |
| Class<?> queryType = classes.nextElement(); |
| Writer writer = getSession().getLog(); |
| try { |
| writer.write(summaries.get(queryType).toString()); |
| writer.write(Helper.cr()); |
| } catch (IOException ioe) { |
| } |
| } |
| } |
| |
| /** |
| * INTERNAL: |
| * Finish a profile operation if profiling. |
| * This assumes the start operation proceeds on the stack. |
| * The session must be passed to allow units of work etc. to share their parents profiler. |
| * |
| * @return the execution result of the query. |
| */ |
| @Override |
| @SuppressWarnings({"unchecked"}) |
| public Object profileExecutionOfQuery(DatabaseQuery query, DataRecord row, AbstractSession session) { |
| long profileStartTime = System.nanoTime(); |
| long nestedProfileStartTime = getProfileTime(); |
| Profile profile = new Profile(); |
| profile.setQueryClass(query.getClass()); |
| profile.setDomainClass(query.getReferenceClass()); |
| Writer writer = getSession().getLog(); |
| |
| Object result = null; |
| try { |
| if (shouldLogProfile()) { |
| writeNestingTabs(writer); |
| writer.write(ToStringLocalization.buildMessage("begin_profile_of", null) + "{" + query + Helper.cr()); |
| writer.flush(); |
| } |
| |
| setNestLevel(getNestLevel() + 1); |
| long startNestTime = getNestTime(); |
| Map<String, Long> timingsBeforeExecution = (Map<String, Long>)((Hashtable<String, Long>)getOperationTimings()).clone(); |
| Map<String, Long> startTimingsBeforeExecution = (Map<String, Long>)((Hashtable<String, Long>)getOperationStartTimes()).clone(); |
| long startTime = System.nanoTime(); |
| try { |
| result = session.internalExecuteQuery(query, (AbstractRecord)row); |
| return result; |
| } finally { |
| long endTime = System.nanoTime(); |
| setNestLevel(getNestLevel() - 1); |
| |
| for (String name : getOperationTimings().keySet()) { |
| Long operationStartTime = timingsBeforeExecution.get(name); |
| long operationEndTime = getOperationTimings().get(name); |
| long operationTime; |
| if (operationStartTime != null) { |
| operationTime = operationEndTime - operationStartTime; |
| } else { |
| operationTime = operationEndTime; |
| } |
| profile.addTiming(name, operationTime); |
| } |
| |
| profile.setTotalTime((endTime - startTime) - (getProfileTime() - nestedProfileStartTime));// Remove the profile time from the total time.;); |
| profile.setLocalTime(profile.getTotalTime() - (getNestTime() - startNestTime)); |
| if (result instanceof Collection) { |
| profile.setNumberOfInstancesEffected(((Collection)result).size()); |
| } else { |
| profile.setNumberOfInstancesEffected(1); |
| } |
| |
| addProfile(profile); |
| if (shouldLogProfile()) { |
| writeNestingTabs(writer); |
| long profileEndTime = System.nanoTime(); |
| long totalTimeIncludingProfiling = profileEndTime - profileStartTime;// Try to remove the profiling time from the total time. |
| profile.setProfileTime(totalTimeIncludingProfiling - profile.getTotalTime()); |
| profile.write(writer, this); |
| writer.write(Helper.cr()); |
| writeNestingTabs(writer); |
| writer.write("}" + ToStringLocalization.buildMessage("end_profile", null)); |
| writer.write(Helper.cr()); |
| writer.flush(); |
| } |
| |
| if (getNestLevel() == 0) { |
| setNestTime(0); |
| setProfileTime(0); |
| setOperationTimings(new Hashtable<>()); |
| setOperationStartTimes(new Hashtable<>()); |
| long profileEndTime = System.nanoTime(); |
| long totalTimeIncludingProfiling = profileEndTime - profileStartTime;// Try to remove the profiling time from the total time. |
| profile.setProfileTime(totalTimeIncludingProfiling - profile.getTotalTime()); |
| } else { |
| setNestTime(startNestTime + profile.getTotalTime()); |
| setOperationTimings(timingsBeforeExecution); |
| setOperationStartTimes(startTimingsBeforeExecution); |
| long profileEndTime = System.nanoTime(); |
| long totalTimeIncludingProfiling = profileEndTime - profileStartTime;// Try to remove the profiling time from the total time. |
| setProfileTime(getProfileTime() + (totalTimeIncludingProfiling - (endTime - startTime))); |
| profile.setProfileTime(totalTimeIncludingProfiling - profile.getTotalTime()); |
| for (String timingName : ((Map<String, Long>)(((Hashtable<String, Long>)startTimingsBeforeExecution).clone())).keySet()) { |
| startTimingsBeforeExecution.put(timingName, ((Number) startTimingsBeforeExecution.get(timingName)).longValue() + totalTimeIncludingProfiling); |
| } |
| } |
| } |
| } catch (IOException ioe) { |
| } |
| return result; |
| } |
| |
| protected void setNestLevel(int nestLevel) { |
| this.nestLevel = nestLevel; |
| } |
| |
| protected void setNestTime(long nestTime) { |
| this.nestTime = nestTime; |
| } |
| |
| protected void setOperationStartTimes(Map<String, Long> operationStartTimes) { |
| Integer threadId = Thread.currentThread().hashCode(); |
| getOperationStartTimesByThread().put(threadId, operationStartTimes); |
| } |
| |
| protected void setOperationStartTimesByThread(Map<Integer, Map<String, Long>> operationStartTimesByThread) { |
| this.operationStartTimesByThread = operationStartTimesByThread; |
| } |
| |
| protected void setOperationTimings(Map<String, Long> operationTimings) { |
| Integer threadId = Thread.currentThread().hashCode(); |
| getOperationTimingsByThread().put(threadId, operationTimings); |
| } |
| |
| protected void setOperationTimingsByThread(Map<Integer, Map<String, Long>> operationTimingsByThread) { |
| this.operationTimingsByThread = operationTimingsByThread; |
| } |
| |
| protected void setProfiles(Vector<Profile> profiles) { |
| this.profiles = profiles; |
| } |
| |
| protected void setProfileTime(long profileTime) { |
| this.profileTime = profileTime; |
| } |
| |
| @Override |
| public void setSession(org.eclipse.persistence.sessions.Session session) { |
| this.session = (AbstractSession)session; |
| } |
| |
| /** |
| * PUBLIC: |
| * Set whether after each query execution the profile result should be logged. |
| * By default this is true. |
| */ |
| public void setShouldLogProfile(boolean shouldLogProfile) { |
| this.shouldLogProfile = shouldLogProfile; |
| } |
| |
| public boolean shouldLogProfile() { |
| return shouldLogProfile; |
| } |
| |
| /** |
| * INTERNAL: |
| * Start the operation timing. |
| */ |
| @Override |
| public void startOperationProfile(String operationName) { |
| getOperationStartTimes().put(operationName, System.nanoTime()); |
| } |
| |
| /** |
| * INTERNAL: |
| * Start the operation timing. |
| */ |
| @Override |
| public void startOperationProfile(String operationName, DatabaseQuery query, int weight) { |
| startOperationProfile(operationName); |
| } |
| |
| protected void writeNestingTabs(Writer writer) { |
| try { |
| for (int index = 0; index < getNestLevel(); index++) { |
| writer.write("\t"); |
| } |
| } catch (IOException ioe) { |
| } |
| } |
| |
| @Override |
| public int getProfileWeight() { |
| return -1; |
| } |
| |
| @Override |
| public void initialize() { |
| } |
| } |