数据量大10倍，处理时间不是大10倍

一直想说明数据量大了以后会有各类各样的问题，如数据库中记录数过大致使索引没法所有加载，Linux中swap使用后对性能产生影响等。但一直都没法找到一个合适的例子，每一个例子背后都会牵连一大堆原理/缘由。 java

昨天为了测试经过Sax方式解析XML的性能，须要生成一个200MB的XML文件。为实现简单经过jdom构造XML文件，在生成文件的过程当中遇到了一个有趣的状况，很能说明数据量和处理时间的问题。 shell

本文将描述下遇到的状况，不对相应的内容或缘由做解析。 数据库

经过生成140W记录，生成月200MB的文件。 dom

package com.wb;

import java.io.BufferedOutputStream;
import java.io.File;
import java.io.FileOutputStream;
import java.io.IOException;
import java.text.SimpleDateFormat;
import java.util.Date;

import org.jdom2.Document;
import org.jdom2.Element;
import org.jdom2.output.Format;
import org.jdom2.output.XMLOutputter;

public class XMLGenerator {
public static void main(String[] args) {
Element rootElement = new Element("OBJECTSINFO");
Document doc = new Document(rootElement);

long startMills = System.currentTimeMillis();
System.out.println("Start -- " + startMills);
long lastMills = startMills;
for (long idx = 0; idx < (140 * 1000 * 10); idx++) {
addVoltRateRecord(rootElement, idx);
if ((idx + 1) % (1E4) == 0) {
long curMills = System.currentTimeMillis();
System.out.println("Records Added: " + (idx + 1) + ", Mills Consumed: " + (curMills - lastMills)
+ ", CurTime: " + new SimpleDateFormat("HH:mm:ss").format(new Date(curMills)));
lastMills = curMills;
}
}

long generateMills = System.currentTimeMillis();
System.out.println("Generate XML -- " + (generateMills - startMills));
XMLOutputter outputter = new XMLOutputter(Format.getPrettyFormat().setEncoding("UTF-8"));
File file = new File("D:/testXML.xml");
try {
FileOutputStream outstream = new FileOutputStream(file);
BufferedOutputStream buffOutStream = new BufferedOutputStream(outstream);
outputter.output(doc, buffOutStream);
buffOutStream.close();
} catch (IOException e) {
e.printStackTrace();
}

long savedMills = System.currentTimeMillis();
System.out.println("File Size: " + file.length() + ", Saved XML -- " + (savedMills - generateMills));
}

private static void addVoltRateRecord(Element rootElement, long idx) {
Element voltEle = new Element("VOLTAGE");
voltEle.setAttribute("ROWS", String.valueOf(idx + 1));
rootElement.addContent(voltEle);

Element mpEle = new Element("MEASUREPOINTID");
mpEle.setText("MPID-" + (idx + 1));
voltEle.addContent(mpEle);

Element startTimeEle = new Element("STARTTIME");
mpEle.setText("2012-12-03 09:00:00");
voltEle.addContent(startTimeEle);

Element endTimeEle = new Element("ENDTIME");
mpEle.setText("2012-12-03 10:00:00");
voltEle.addContent(endTimeEle);

Element dataItemEle = new Element("DATAITEM");
mpEle.setText("8E13");
voltEle.addContent(dataItemEle);

Element valueEle = new Element("VALUE");
mpEle.setText("239.000");
voltEle.addContent(valueEle);
}
}

运行配置的环境为JDK1.5.22，-Xmx2048m，具体环境以下： 性能

运行结果输出为： 测试

Start -- 1356174199593
Records Added: 10000, Mills Consumed: 329, CurTime: 19:03:19
Records Added: 20000, Mills Consumed: 249, CurTime: 19:03:20
Records Added: 30000, Mills Consumed: 336, CurTime: 19:03:20
Records Added: 40000, Mills Consumed: 418, CurTime: 19:03:20
Records Added: 50000, Mills Consumed: 513, CurTime: 19:03:21
Records Added: 60000, Mills Consumed: 570, CurTime: 19:03:22
Records Added: 70000, Mills Consumed: 894, CurTime: 19:03:22
Records Added: 80000, Mills Consumed: 906, CurTime: 19:03:23
Records Added: 90000, Mills Consumed: 1060, CurTime: 19:03:24
Records Added: 100000, Mills Consumed: 965, CurTime: 19:03:25
Records Added: 110000, Mills Consumed: 1027, CurTime: 19:03:26
Records Added: 120000, Mills Consumed: 1161, CurTime: 19:03:28
Records Added: 130000, Mills Consumed: 1233, CurTime: 19:03:29
Records Added: 140000, Mills Consumed: 1331, CurTime: 19:03:30
Records Added: 150000, Mills Consumed: 1369, CurTime: 19:03:31
Records Added: 160000, Mills Consumed: 1460, CurTime: 19:03:33
Records Added: 170000, Mills Consumed: 1709, CurTime: 19:03:35
Records Added: 180000, Mills Consumed: 1877, CurTime: 19:03:37
Records Added: 190000, Mills Consumed: 1966, CurTime: 19:03:38
Records Added: 200000, Mills Consumed: 2235, CurTime: 19:03:41
Records Added: 210000, Mills Consumed: 2376, CurTime: 19:03:43
Records Added: 220000, Mills Consumed: 2611, CurTime: 19:03:46
Records Added: 230000, Mills Consumed: 2673, CurTime: 19:03:48
Records Added: 240000, Mills Consumed: 2793, CurTime: 19:03:51
Records Added: 250000, Mills Consumed: 2760, CurTime: 19:03:54
Records Added: 260000, Mills Consumed: 2928, CurTime: 19:03:57
Records Added: 270000, Mills Consumed: 3079, CurTime: 19:04:00
Records Added: 280000, Mills Consumed: 3125, CurTime: 19:04:03
Records Added: 290000, Mills Consumed: 3286, CurTime: 19:04:06
Records Added: 300000, Mills Consumed: 4164, CurTime: 19:04:10
Records Added: 310000, Mills Consumed: 3554, CurTime: 19:04:14
Records Added: 320000, Mills Consumed: 3720, CurTime: 19:04:18
Records Added: 330000, Mills Consumed: 3738, CurTime: 19:04:22
Records Added: 340000, Mills Consumed: 3835, CurTime: 19:04:25
Records Added: 350000, Mills Consumed: 3988, CurTime: 19:04:29
Records Added: 360000, Mills Consumed: 4351, CurTime: 19:04:34
Records Added: 370000, Mills Consumed: 4237, CurTime: 19:04:38
Records Added: 380000, Mills Consumed: 4263, CurTime: 19:04:42
Records Added: 390000, Mills Consumed: 4331, CurTime: 19:04:47
Records Added: 400000, Mills Consumed: 4430, CurTime: 19:04:51
Records Added: 410000, Mills Consumed: 4591, CurTime: 19:04:56
Records Added: 420000, Mills Consumed: 4683, CurTime: 19:05:00
Records Added: 430000, Mills Consumed: 5029, CurTime: 19:05:05
Records Added: 440000, Mills Consumed: 5356, CurTime: 19:05:11
Records Added: 450000, Mills Consumed: 5349, CurTime: 19:05:16
Records Added: 460000, Mills Consumed: 5207, CurTime: 19:05:21
Records Added: 470000, Mills Consumed: 5414, CurTime: 19:05:27
Records Added: 480000, Mills Consumed: 5546, CurTime: 19:05:32
Records Added: 490000, Mills Consumed: 5606, CurTime: 19:05:38
Records Added: 500000, Mills Consumed: 5793, CurTime: 19:05:44
Records Added: 510000, Mills Consumed: 5757, CurTime: 19:05:49
Records Added: 520000, Mills Consumed: 5911, CurTime: 19:05:55
Records Added: 530000, Mills Consumed: 6053, CurTime: 19:06:01
Records Added: 540000, Mills Consumed: 6151, CurTime: 19:06:07
Records Added: 550000, Mills Consumed: 6230, CurTime: 19:06:14
Records Added: 560000, Mills Consumed: 6469, CurTime: 19:06:20
Records Added: 570000, Mills Consumed: 6545, CurTime: 19:06:27
Records Added: 580000, Mills Consumed: 7041, CurTime: 19:06:34
Records Added: 590000, Mills Consumed: 7030, CurTime: 19:06:41
Records Added: 600000, Mills Consumed: 6988, CurTime: 19:06:48
Records Added: 610000, Mills Consumed: 7167, CurTime: 19:06:55
Records Added: 620000, Mills Consumed: 7426, CurTime: 19:07:02
Records Added: 630000, Mills Consumed: 7162, CurTime: 19:07:09
Records Added: 640000, Mills Consumed: 7520, CurTime: 19:07:17
Records Added: 650000, Mills Consumed: 7567, CurTime: 19:07:25
Records Added: 660000, Mills Consumed: 7676, CurTime: 19:07:32
Records Added: 670000, Mills Consumed: 7552, CurTime: 19:07:40
Records Added: 680000, Mills Consumed: 7723, CurTime: 19:07:47
Records Added: 690000, Mills Consumed: 7785, CurTime: 19:07:55
Records Added: 700000, Mills Consumed: 8269, CurTime: 19:08:04
Records Added: 710000, Mills Consumed: 9782, CurTime: 19:08:13
Records Added: 720000, Mills Consumed: 8316, CurTime: 19:08:22
Records Added: 730000, Mills Consumed: 8441, CurTime: 19:08:30
Records Added: 740000, Mills Consumed: 8534, CurTime: 19:08:39
Records Added: 750000, Mills Consumed: 8737, CurTime: 19:08:47
Records Added: 760000, Mills Consumed: 8597, CurTime: 19:08:56
Records Added: 770000, Mills Consumed: 8799, CurTime: 19:09:05
Records Added: 780000, Mills Consumed: 8971, CurTime: 19:09:14
Records Added: 790000, Mills Consumed: 9096, CurTime: 19:09:23
Records Added: 800000, Mills Consumed: 9220, CurTime: 19:09:32
Records Added: 810000, Mills Consumed: 9377, CurTime: 19:09:41
Records Added: 820000, Mills Consumed: 9517, CurTime: 19:09:51
Records Added: 830000, Mills Consumed: 9548, CurTime: 19:10:00
Records Added: 840000, Mills Consumed: 9689, CurTime: 19:10:10
Records Added: 850000, Mills Consumed: 9985, CurTime: 19:10:20
Records Added: 860000, Mills Consumed: 11295, CurTime: 19:10:31
Records Added: 870000, Mills Consumed: 10574, CurTime: 19:10:42
Records Added: 880000, Mills Consumed: 10297, CurTime: 19:10:52
Records Added: 890000, Mills Consumed: 10312, CurTime: 19:11:03
Records Added: 900000, Mills Consumed: 10391, CurTime: 19:11:13
Records Added: 910000, Mills Consumed: 10484, CurTime: 19:11:24
Records Added: 920000, Mills Consumed: 10890, CurTime: 19:11:34
Records Added: 930000, Mills Consumed: 10812, CurTime: 19:11:45
Records Added: 940000, Mills Consumed: 11030, CurTime: 19:11:56
Records Added: 950000, Mills Consumed: 10936, CurTime: 19:12:07
Records Added: 960000, Mills Consumed: 10937, CurTime: 19:12:18
Records Added: 970000, Mills Consumed: 11389, CurTime: 19:12:29
Records Added: 980000, Mills Consumed: 11498, CurTime: 19:12:41
Records Added: 990000, Mills Consumed: 11561, CurTime: 19:12:53
Records Added: 1000000, Mills Consumed: 11545, CurTime: 19:13:04
Records Added: 1010000, Mills Consumed: 11561, CurTime: 19:13:16
Records Added: 1020000, Mills Consumed: 12215, CurTime: 19:13:28
Records Added: 1030000, Mills Consumed: 12544, CurTime: 19:13:40
Records Added: 1040000, Mills Consumed: 12387, CurTime: 19:13:53
Records Added: 1050000, Mills Consumed: 12403, CurTime: 19:14:05
Records Added: 1060000, Mills Consumed: 12278, CurTime: 19:14:17
Records Added: 1070000, Mills Consumed: 12918, CurTime: 19:14:30
Records Added: 1080000, Mills Consumed: 13324, CurTime: 19:14:44
Records Added: 1090000, Mills Consumed: 12871, CurTime: 19:14:57
Records Added: 1100000, Mills Consumed: 12668, CurTime: 19:15:09
Records Added: 1110000, Mills Consumed: 12793, CurTime: 19:15:22
Records Added: 1120000, Mills Consumed: 13308, CurTime: 19:15:35
Records Added: 1130000, Mills Consumed: 13822, CurTime: 19:15:49
Records Added: 1140000, Mills Consumed: 13558, CurTime: 19:16:03
Records Added: 1150000, Mills Consumed: 13635, CurTime: 19:16:16
Records Added: 1160000, Mills Consumed: 13823, CurTime: 19:16:30
Records Added: 1170000, Mills Consumed: 18565, CurTime: 19:16:49
Records Added: 1180000, Mills Consumed: 13308, CurTime: 19:17:02
Records Added: 1190000, Mills Consumed: 23604, CurTime: 19:17:26
Records Added: 1200000, Mills Consumed: 82587, CurTime: 19:18:48
Records Added: 1210000, Mills Consumed: 106549, CurTime: 19:20:35
Records Added: 1220000, Mills Consumed: 113478, CurTime: 19:22:28
Records Added: 1230000, Mills Consumed: 116785, CurTime: 19:24:25
Records Added: 1240000, Mills Consumed: 121567, CurTime: 19:26:27
Records Added: 1250000, Mills Consumed: 123820, CurTime: 19:28:30
Records Added: 1260000, Mills Consumed: 127239, CurTime: 19:30:38

对应的Heap内存使用状况： code

对应的CPU使用率： orm