001: /*
002:
003: This software is OSI Certified Open Source Software.
004: OSI Certified is a certification mark of the Open Source Initiative.
005:
006: The license (Mozilla version 1.0) can be read at the MMBase site.
007: See http://www.MMBase.org/license
008:
009: */
010: package org.mmbase.util.logging;
011:
012: import org.mmbase.util.ResourceLoader;
013: import org.apache.log4j.Category;
014: import org.apache.log4j.xml.DOMConfigurator;
015:
016: /**
017: * This program is meant to show the performance of the
018: * org.mmbase.util.logging classes. You can also easily check the
019: * performance of a configuration with it. Simply feed it the configuration file, and it will
020: * try to log (info priority) to the class A0123456789.B0123456789.C0123456789.
021: * It has several other command line options (starting with -).
022: *
023: **/
024:
025: public class Performance {
026:
027: static final double SECOND = 1000; // one second in milliseconds.
028:
029: static int repeats = 1000;
030: static boolean isdebugenabled = false;
031: static boolean nosystem = false;
032: static boolean log4j = false;
033: static String description = null;
034: static boolean delay = false;
035: static int delaytime = 10;
036: static int burstLen = 3;
037: static int warmingup = 200;
038:
039: static double doCaseLog4j(String s) {
040: DOMConfigurator.configure(s);
041: int i;
042: Category cat = Category
043: .getInstance("A0123456789.B0123456789.C0123456789");
044: for (i = 0; i < warmingup; i++) {
045: cat.info("warming up.");
046: }
047: long before = System.currentTimeMillis();
048: for (i = 0; i < repeats; i++) {
049: cat
050: .info("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890");
051: }
052: long after = System.currentTimeMillis();
053: return (double) 1000 * (after - before) / repeats;
054:
055: }
056:
057: static double doCaseNoSystem() {
058: int i;
059: for (i = 0; i < warmingup; i++) {
060: System.err.println("warming up.");
061: }
062: long before = System.currentTimeMillis();
063: for (i = 0; i < repeats; i++) {
064: System.err
065: .println("INFO abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890");
066: }
067: long after = System.currentTimeMillis();
068: return (double) 1000 * (after - before) / repeats;
069: }
070:
071: static double doCase(Logger log) {
072: if (delay) {
073: return doCaseDelayed(log);
074: }
075: int i;
076: for (i = 0; i < warmingup; i++) {
077: log.info("warming up.");
078: }
079: long before = System.currentTimeMillis();
080: for (i = 0; i < repeats; i++) {
081: log
082: .info("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890");
083: }
084: long after = System.currentTimeMillis();
085: return (double) 1000 * (after - before) / repeats;
086: }
087:
088: static double doCaseDelayed(Logger log) {
089: int j = 0;
090: int i;
091: try {
092: // Warming up makes the results better reproducable.
093: for (i = 0; i < warmingup; i++) {
094: log.info("warming up.");
095: if (++j == burstLen) {
096: j = 0;
097: Thread.sleep(delaytime);
098: }
099: }
100: long before = System.currentTimeMillis();
101: for (i = 0; i < repeats; i++) {
102: log
103: .info("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890");
104: if (++j == burstLen) {
105: j = 0;
106: Thread.sleep(delaytime);
107: }
108: }
109: long after = System.currentTimeMillis();
110: j = 0;
111: // sleep a little in between.
112: Thread.sleep(3000);
113:
114: long before_ref = System.currentTimeMillis();
115: // do the same but without logging (trace will not be logged, and we've seen that it's time is neglectable).
116: for (i = 0; i < repeats; i++) {
117: log
118: .trace("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890");
119: if (j++ == burstLen) {
120: j = 0;
121: Thread.sleep(delaytime);
122: }
123: }
124:
125: long after_ref = System.currentTimeMillis();
126:
127: //System.out.println("(with: " + (after - before) + " without " + (after_ref - before_ref) + " ) ");
128: return (double) 1000
129: * (after - before - (after_ref - before_ref))
130: / repeats;
131: } catch (Exception e) {
132: }
133: return 0;
134: }
135:
136: static double doCaseIfDebug(Logger log) {
137: int i;
138: for (i = 0; i < warmingup; i++) {
139: if (log.isDebugEnabled()) {
140: log.debug("warming up.");
141: }
142: }
143: long before = System.currentTimeMillis();
144: for (i = 0; i < repeats; i++) {
145: if (log.isDebugEnabled()) {
146: log
147: .debug("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890");
148: }
149: }
150: long after = System.currentTimeMillis();
151: return (double) 1000 * (after - before) / repeats;
152: }
153:
154: static double Case(String configuration) {
155: if (log4j) {
156: return doCaseLog4j(configuration);
157: }
158: if (nosystem) {
159: return doCaseNoSystem();
160: }
161:
162: Logging.configure(ResourceLoader.getConfigurationRoot(),
163: configuration);
164: Logger log = Logging
165: .getLoggerInstance("A0123456789.B0123456789.C0123456789");
166:
167: if (isdebugenabled) {
168: return doCaseIfDebug(log);
169: } else {
170: return doCase(log);
171: }
172:
173: }
174:
175: static void printCase(String configuration) {
176: String s = (description == null ? "" : description) + " ("
177: + configuration + ") : ";
178: for (int i = s.length(); i < 50; i++)
179: s += " "; // damn, sprintf would be nice..
180: System.out.print(s);
181:
182: double benchmark = Case(configuration);
183:
184: System.out.println(benchmark + " us/logging"); // we follow the example of log4j and report in microseconds (us)
185: }
186:
187: public static void main(String[] args) {
188: for (int i = 0; i < args.length; i++) {
189: if (args[i].charAt(0) == '-') { // an command line option
190: if (args[i].substring(1).equals("repeats")) {
191: repeats = Integer.valueOf(args[++i]).intValue();
192: }
193: if (args[i].substring(1).equals("isdebugenabled")) {
194: isdebugenabled = !isdebugenabled;
195: }
196: if (args[i].substring(1).equals("nosystem")) {
197: nosystem = !nosystem;
198: }
199: if (args[i].substring(1).equals("log4j")) {
200: log4j = !log4j;
201: }
202: if (args[i].substring(1).equals("desc")) {
203: description = args[++i];
204: }
205: if (args[i].substring(1).equals("delay")) {
206: delay = !delay;
207: }
208: if (args[i].substring(1).equals("delaytime")) {
209: delaytime = Integer.valueOf(args[++i]).intValue();
210: }
211: if (args[i].substring(1).equals("burstlen")) {
212: burstLen = Integer.valueOf(args[++i]).intValue();
213: }
214: } else {
215: warmingup = repeats / 10;
216: printCase(args[i]);
217: }
218: }
219: Logging.shutdown();
220: }
221: }
|