0

How does PerformanceMeter and Statistic work?

asked 2009-03-17 16:12:32 +0800

OverFlo123 gravatar image OverFlo123
63 5

I have added the "PerformanceMeter" listener to the zk.xml but what now?

How and where are the performance statistics generated?
Is there an example somewhere?

btw "Mointor the statistic" with org.zkoss.zk.ui.util.Statistic?
how wnd where are the statistics monitored?

please help, I need to fix some performance issus.


kind regards

florian

delete flag offensive retag edit

14 Replies

Sort by » oldest newest

answered 2009-03-19 14:44:25 +0800

madruga0315 gravatar image madruga0315 flag of Brazil
937 2 12

Hi,

I also have some doubts about how PerformanceMeter works, apperently the life cycle described for zk 3.5 has changed in zk 3.6

Can some zk guru give some more in depth explanation of how this works?

Regards,
Madruga

link publish delete flag offensive edit

answered 2009-03-19 19:19:00 +0800

madruga0315 gravatar image madruga0315 flag of Brazil
937 2 12

Hi again,

While doing some tests I guess that I figured it out how zk performance meter works.

Start Client -> Start Server -> Completed Server -> Received Client -> Completed Client

And as far as I understood the calculation of one execution is done in the next execution, please correct here if I'm wrong.

Now, the performance monitor depends on the requestId variable, is there some way to retrieve it in my EventInterceptor implementation (guessing that it should be in current execution)?

Below in my implementation of the PerformanceMonitor written in groovy

package zk.monitor

import org.zkoss.zk.ui.util.PerformanceMeter
import org.zkoss.zk.ui.Execution
import org.apache.log4j.Logger

public class RedAlertPerformanceMeter implements PerformanceMeter {
    static Logger LOG = Logger.getLogger(RedAlertPerformanceMeter.class)
    LinkedHashMap map = new LinkedHashMap(300)

    // performance always starts here
    @Override
    public void requestStartAtClient(String requestId, Execution exec, long time) {
        //RedAlertPerformanceMeter.LOG.info "SC reqId: ${requestId}, time: ${time}"
        def execId = exec.toString().split(':')[0].substring(1)
        def deskId = exec.desktop.id
        def rapt = new RedAlertPerformanceTime(execId: execId, scTime: time, deskId: deskId, reqId: requestId)
        this.map.put(requestId, rapt)
    }

    @Override
    public void requestStartAtServer(String requestId, Execution exec, long time) {
        //RedAlertPerformanceMeter.LOG.info "SS reqId: ${requestId}, time: ${time}"
        if(map.containsKey(requestId)) {
            RedAlertPerformanceTime rapt = map.get(requestId)
            rapt.ssTime = time
        }
    }

    @Override
    public void requestCompleteAtServer(String requestId, Execution exec, long time) {
        //RedAlertPerformanceMeter.LOG.info "CS reqId: ${requestId}, time: ${time}"
        if(map.containsKey(requestId)) {
            RedAlertPerformanceTime rapt = map.get(requestId)
            rapt.csTime = time
        }
    }

    @Override
    public void requestReceiveAtClient(String requestId, Execution exec, long time) {
        //RedAlertPerformanceMeter.LOG.info "RC reqId: ${requestId}, time: ${time}"
        if(map.containsKey(requestId)) {
            RedAlertPerformanceTime rapt = map.get(requestId)
            rapt.rcTime = time
        }
    }

    // performance always end here
    @Override
    public void requestCompleteAtClient(String requestId, Execution exec, long time) {
        //RedAlertPerformanceMeter.LOG.info "CC reqId: ${requestId}, time: ${time}"
        if(map.containsKey(requestId)) {
            RedAlertPerformanceTime rapt = map.get(requestId)
            rapt.ccTime = time
            rapt.avaliateThresholdAndLog()
            // execution logged can be removed from map
            map.remove(rapt)
            // need this?
            if(map.size() >= 300) {
                map.clear()
            }
        }
    }
}

/**
 * Class to encapsulate performance variables
 */
public class RedAlertPerformanceTime {
    /** 1 - start client time */
    long scTime = -1
    /** 2 - start server time */
    long ssTime = -1
    /** 3 - completed server time */
    long csTime = -1
    /** 4 - received client time */
    long rcTime = -1
    /** 5 - completed client time */
    long ccTime = -1

    String execId
    String deskId
    String reqId

    /**
     * Avaliates if the process time exceeds an defined time of 5 seconds.
     * If exceeds log this as error which will be sent to developer mail.
     * If under 5 seconds log as info.
     */
    //TODO the max processing time should be a system variable
    void avaliateThresholdAndLog() {
        def total = this.ccTime - this.scTime

        // if total processing time exceeds 5 seconds log as error to optmize
        if(total > 5000) {
            RedAlertPerformanceMeter.LOG.error "process takes too long ${this}"
        } else {
            RedAlertPerformanceMeter.LOG.info "process takes too long ${this}"
        }
    }

    @Override
    String toString() {
        int totalTime = this.ccTime - this.scTime
        "d: ${deskId}, e: ${execId}, reqId: ${reqId}, totalTime: ${totalTime}"
    }
}

link publish delete flag offensive edit

answered 2009-03-20 11:21:02 +0800

OverFlo123 gravatar image OverFlo123
63 5

using my debugger it looks more like (using zk 3.6.0)
if I click on one of my UI Elements (button or list item):


Received Client -> Completed Client -> Start Client -> Start Server -> Completed Server


what I am missing is the time it takes the Client to render the results of the server answer!


so please if one of the ZK "gurus" can shed some light on this issue!

regards

flo

link publish delete flag offensive edit

answered 2009-03-20 14:05:50 +0800

OverFlo123 gravatar image OverFlo123
63 5

btw - is there a way to get the UI element which generated the request?
(there´s a lot of stuff in "Execution" but I can´s seem to find something like an Id or so...)

because it would be nice to know which performance values belong to which action !

florian

link publish delete flag offensive edit

answered 2009-03-20 22:14:46 +0800

madruga0315 gravatar image madruga0315 flag of Brazil
937 2 12

Hi Florian,

If we analyze the chronological order of events, then the order that you informed is the correct one. But the performance depends on the requestId variable. And if you analyze the the chronological order but taking in account the requestId, you'll see that the order that I informed is the correct one.

So for your first question, the time the the client takes to draw the results receveid from server is the time Completed At Client minus Received at Client, both times having the same requestId.

Regards,
Madruga

link publish delete flag offensive edit

answered 2009-03-24 09:55:59 +0800

OverFlo123 gravatar image OverFlo123
63 5

Thanks - that makes perfect sense!

any possibility to get the "id" of the GUI Component which sent the request?

link publish delete flag offensive edit

answered 2009-03-25 14:24:12 +0800

OverFlo123 gravatar image OverFlo123
63 5

another Question - I click a button and get these values:

Client recev: gjf81-8 = 15:21:03 / 1237990863728 ([Exec16795510: [Desktop gjf81]])
Client cmplt: gjf81-8 = 15:21:03 / 1237990863824 ([Exec16795510: [Desktop gjf81]])
Client start: gjf81-9 = 15:22:33 / 1237990953277 ([Exec16795510: [Desktop gjf81]])
Server start: gjf81-9 = 15:22:33 / 1237990953293 ([Exec16795510: [Desktop gjf81]])
Server cmplt: gjf81-9 = 15:22:33 / 1237990953313 ([Exec16795510: [Desktop gjf81]])

so why are there different requestIds for one request?

and why are the client complete before the server complete?


any ideas?

flo

link publish delete flag offensive edit

answered 2009-04-01 15:50:17 +0800

robbiecheng gravatar image robbiecheng
1144 2
http://robbiecheng.sys-co...

Hi florian,

it will be best if you can provide your example code, so we can replicate this issue.

thanks,
robbie

link publish delete flag offensive edit

answered 2009-06-05 12:13:58 +0800

edudant gravatar image edudant
219 1 1 1
zk.datalite.cz

updated 2009-06-05 12:15:08 +0800

I did some tests with this monitor. For one desktop:
First request -> start at client time is missing
Between -> All times are set
Last request -> recieved at client and complete at client is missing

Which makes perfect sense - ZK holds these infomrations in desktop and updates client information in next reqest.

I didn't find any hint about execution source (e.g. button click) to add to the log. However it may be good idea to combine this with Spring AOP and append calls on my controller class - then i can add information like ( myController.onAddPerson() ). I can even add statistics how long my business code takes in comparison to overall server code.

link publish delete flag offensive edit

answered 2009-06-05 13:15:15 +0800

sousa1981 gravatar image sousa1981
573 4

You can create an file for example at package com.xxx.Statistic.java (I stole the source code from ZK package "org.zkoss.zk.ui.util")

Configure it at zk.xml
<!-- Optional -->
<!-- the following listener is used to see # of sessions, desktops...
-->
<listener>
<description>My Own Monitor statistic</description>
<listener-class>com.xxx.Statistic</listener-class>
</listener>

Just create an log.

import java.util.List;

import org.zkoss.zk.ui.Session;
import org.zkoss.zk.ui.Desktop;

/**
 * An implementation of {@link Monitor} to accumulate statistic data
 * in memory.
 *
 * <p>It has no effect until you specify it in WEB-INF/zk.xml.
 *
 * @author tomyeh
 */
public class Statistic implements Monitor {
	private final long _startTime;
	private int _nsess, _actsess, _ndt, _actdt, _nupd, _actupd;

	public Statistic() {
		_startTime = System.currentTimeMillis();
	}

	/** Returns when the server (actually, this monitor) started.
	 */
	public long getStartTime() {
		return _startTime;
	}

	/** Returns the total number of sessions that have been created
	 * since the server started.
	 */
	public int getTotalSessionCount() {
		return _nsess;
	}
	/** Returns the number of active sessions.
	 */
	public int getActiveSessionCount() {
		return _actsess;
	}
	/** Returns the average number of sessions being created in an hour.
	 */
	public double getAverageSessionCount() {
		return _nsess / getEscapedHours();
	}

	/** Returns the total number of desktops that have been created
	 * since the server started.
	 */
	public int getTotalDesktopCount() {
		return _ndt;
	}
	/** Returns the number of active desktops.
	 */
	public int getActiveDesktopCount() {
		return _actdt;
	}
	/** Returns the average number of desktops being created in an hour.
	 */
	public double getAverageDesktopCount() {
		return _ndt / getEscapedHours();
	}

	/** Returns the total number of asynchronous updates that have been received
	 * since the server started.
	 */
	public int getTotalUpdateCount() {
		return _nupd;
	}
	/** Returns the number of active asynchronous updates.
	 */
	public int getActiveUpdateCount() {
		return _actupd;
	}
	/** Returns the average number of asynchronous updates being created
	 * in an hour.
	 */
	public double getAverageUpdateCount() {
		return _nupd / getEscapedHours();
	}

	/** Returns how many hours escaped since the server started.
	 */
	private double getEscapedHours() {
		long v = System.currentTimeMillis() - _startTime;
		return ((double)v) / 3600000;
	}

	//-- Monitor --//
	synchronized public void sessionCreated(Session sess) {
		++_nsess; ++_actsess;
	}
	synchronized public void sessionDestroyed(Session sess) {
		--_actsess;
	}
	synchronized public void desktopCreated(Desktop desktop) {
		++_ndt; ++_actdt;
	}
	synchronized public void desktopDestroyed(Desktop desktop) {
		--_actdt;
	}
	synchronized public void beforeUpdate(Desktop desktop, List requests) {
		++_nupd; ++_actupd;
	}
	synchronized public void afterUpdate(Desktop desktop) {
		--_actupd;
	}
}


link publish delete flag offensive edit
Your reply
Please start posting your answer anonymously - your answer will be saved within the current session and published after you log in or create a new account. Please try to give a substantial answer, for discussions, please use comments and please do remember to vote (after you log in)!

[hide preview]

Question tools

Follow

RSS

Stats

Asked: 2009-03-17 16:12:32 +0800

Seen: 439 times

Last updated: Jun 17 '09

Support Options
  • Email Support
  • Training
  • Consulting
  • Outsourcing
Learn More