I am using PostgreSQL 7.3.4 on RedHat 9. My application gets slower as
the database gets bigger. I suspected the database and wrote an
extremely simple test: One table with one integer column, declare a
primary key, and insert rows, 1000/transaction. Measure the time for
each transaction.
Detailed observations and the test program appear below.
Is this expected behavior? Is there something I need to tune to avoid
this problem? I've left postgresql.conf alone, except for sort_mem (8
meg).
Jack Orenstein
Transaction times: Each transaction does 1000 inserts. The values
inserted come from a random number generator. These results show the
first 50 transaction, but the trend continues. By the time the
database has about 600,000 rows, I'm seeing transaction times in the
7-10 second range.
Transaction 0: 189 msec
Transaction 1: 141
Transaction 2: 185
Transaction 3: 107
Transaction 4: 473
Transaction 5: 101
Transaction 6: 102
Transaction 7: 184
Transaction 8: 98
Transaction 9: 104
Transaction 10: 185
Transaction 11: 96
Transaction 12: 100
Transaction 13: 188
Transaction 14: 102
Transaction 15: 98
Transaction 16: 184
Transaction 17: 102
Transaction 18: 96
Transaction 19: 198
Transaction 20: 95
Transaction 21: 97
Transaction 22: 199
Transaction 23: 309
Transaction 24: 821
Transaction 25: 1074
Transaction 26: 1051
Transaction 27: 1190
Transaction 28: 1076
Transaction 29: 1305
Transaction 30: 1337
Transaction 31: 1389
Transaction 32: 1476
Transaction 33: 1518
Transaction 34: 1454
Transaction 35: 1601
Transaction 36: 1575
Transaction 37: 1727
Transaction 38: 1687
Transaction 39: 1483
Transaction 40: 1776
Transaction 41: 1913
Transaction 42: 1845
Transaction 43: 1845
Transaction 44: 1971
Transaction 45: 1987
Transaction 46: 1961
Transaction 47: 2177
Transaction 48: 2032
Transaction 49: 2045
2) vmstat output
The first four rows are printed shortly before the program
begins. Once the program begins, bo (blocks out) goes up rapidly and
stats steady, and the CPU is mostly idle.
[jao@jack jao]$ vmstat 1
procs memory swap io system cpu
r b w swpd free buff cache si so bi bo in cs us sy id
1 0 0 916 226384 110480 337044 0 0 64 1167 317 1064 8 2 90
0 0 0 916 226384 110480 337044 0 0 0 0 189 475 0 1 99
0 0 0 916 226376 110480 337044 0 0 0 0 151 778 24 3 73
0 0 0 916 226368 110480 337044 0 0 0 0 198 1550 26 2 72
0 0 0 916 223412 110480 334280 0 0 0 1372 196 4960 82 7 11
2 0 0 916 223412 110480 334600 0 0 0 1620 260 12211 83 14 3
2 0 0 916 223412 110480 335032 0 0 0 2388 241 16842 83 12 5
5 0 0 916 223412 110480 335448 0 0 0 2324 274 18093 86 11 3
0 1 1 916 223420 110484 335624 0 0 0 2496 342 6437 42 8 50
2 1 1 916 223420 110484 335704 0 0 0 1936 379 2628 16 4 80
1 1 1 916 223420 110484 335760 0 0 0 2296 403 2801 13 3 84
1 1 1 916 223420 110484 335808 0 0 0 1992 416 2692 12 2 86
2 1 1 916 223420 110492 335856 0 0 0 2140 392 2500 14 3 83
2 1 1 916 223420 110492 335904 0 0 0 2192 437 2426 11 5 84
0 1 1 916 223372 110496 335960 0 0 0 2328 393 2301 5 6 89
0 1 1 916 223336 110496 336000 0 0 0 2272 455 2184 9 5 86
1 1 1 916 223264 110512 336056 0 0 0 2348 389 2157 11 3 86
1 1 1 916 223220 110516 336096 0 0 0 2260 412 1970 10 5 85
1 1 1 916 223180 110516 336136 0 0 0 2380 397 1985 4 6 90
1 1 1 916 223144 110520 336168 0 0 0 2340 444 2026 14 3 83
1 1 1 916 223096 110520 336216 0 0 0 2572 406 1966 11 3 86
2 1 1 916 223068 110524 336240 0 0 0 2108 443 1764 4 4 92
2 1 1 916 223020 110524 336288 0 0 0 2876 425 2041 10 4 86
1 1 1 916 222992 110528 336312 0 0 0 2124 427 1669 9 6 85
0 1 1 916 222956 110532 336344 0 0 0 2864 441 1991 6 5 89
0 1 1 916 222920 110536 336376 0 0 0 2388 437 1678 8 5 87
0 1 1 916 222888 110544 336400 0 0 0 2116 414 1660 3 5 92
1 0 0 916 222848 110544 336440 0 0 0 2628 473 1779 11 5 84
2 0 0 916 222816 110544 336472 0 0 0 2376 411 1958 9 3 88
0 1 1 916 222792 110544 336496 0 0 0 2724 512 1956 5 4 91
1 1 1 916 222752 110544 336536 0 0 0 2640 416 1790 10 2 88
0 1 1 916 222728 110544 336560 0 0 0 2244 442 1698 12 2 86
2 1 1 916 222704 110544 336584 0 0 0 2260 394 1630 4 1 95
1 1 1 916 222656 110544 336632 0 0 0 2460 446 1803 8 5 87
2 1 1 916 222640 110544 336648 0 0 0 2260 416 1549 4 2 94
0 1 1 916 222616 110544 336672 0 0 0 2568 459 1741 11 2 87
1 1 1 916 222580 110548 336704 0 0 0 2304 407 1545 6 1 93
1 1 1 916 222552 110548 336728 0 0 0 2608 446 1800 10 4 86
1 1 1 916 222528 110548 336752 0 0 0 2344 422 1582 5 2 93
0 1 1 916 222480 110548 336800 0 0 0 2384 417 1557 10 2 88
1 1 1 916 222448 110548 336832 0 0 0 2368 413 1527 6 1 93
1 1 1 916 222416 110548 336864 0 0 0 2432 467 1690 8 7 85
2 1 1 916 222388 110548 336888 0 0 0 2332 432 1598 4 4 92
1 1 1 916 222348 110548 336928 0 0 0 2504 451 1490 7 6 87
2 1 1 916 222324 110548 336952 0 0 0 2296 385 1557 6 4 90
3 0 0 916 222064 110548 336984 0 0 0 2272 453 1879 31 9 60
0 1 1 916 222064 110548 337032 0 0 0 3252 430 1566 6 6 88
1 1 1 916 221984 110548 337056 0 0 0 2716 478 1912 31 4 65
2 1 1 916 221984 110548 337080 0 0 0 2628 451 1572 6 2 92
0 1 1 916 221984 110548 337112 0 0 0 2164 466 1501 9 4 87
0 1 1 916 221984 110548 337144 0 0 0 2900 463 1743 6 3 91
0 1 1 916 221984 110552 337160 0 0 0 2224 495 1473 9 2 89
1 1 1 916 221984 110552 337200 0 0 0 2524 435 1492 5 2 93
0 1 1 916 221984 110560 337232 0 0 0 2204 426 1424 9 3 88
0 1 1 916 221980 110564 337272 0 0 0 2912 464 1666 5 2 93
1 1 1 916 221956 110564 337296 0 0 0 2476 468 1512 11 2 87
2 0 0 916 221928 110568 337320 0 0 0 2544 464 1630 6 3 91
2 1 1 916 221896 110572 337344 0 0 0 2832 523 1567 11 4 86
0 1 1 916 221864 110572 337376 0 0 0 2620 436 1528 6 2 92
0 1 1 916 221848 110572 337392 0 0 0 2564 515 1631 6 3 91
1 0 0 916 221812 110572 337424 0 0 0 2092 440 1452 10 5 85
1 1 1 916 221780 110572 337456 0 0 0 2896 526 1656 4 5 91
0 1 1 916 221756 110572 337480 0 0 0 2128 436 1385 9 2 89
1 1 1 916 221724 110572 337512 0 0 0 2716 499 1523 6 2 92
0 1 1 916 221680 110572 337552 0 0 0 2608 425 1509 9 3 88
2 0 0 916 221656 110572 337576 0 0 0 2092 459 1311 4 4 92
0 1 1 916 221640 110572 337592 0 0 0 2668 436 1562 11 3 86
0 1 1 916 221612 110576 337616 0 0 0 2744 507 1578 5 2 93
Test code:
package com.ris.experiment;
import java.sql.*;
import java.util.Random;
import com.geophile.util.ExceptionPrinter;
import com.ris.util.Stopwatch;
public class InsertPerformance
{
public static void main(String[] args)
{
try {
new InsertPerformance(args).run();
} catch (Throwable termination) {
ExceptionPrinter.print(termination);
}
}
private void run() throws SQLException, ClassNotFoundException, InstantiationException, IllegalAccessException
{
connectToDB();
sql("drop table test");
sql("create table test(id integer, primary key(id))");
PreparedStatement insert = connection.prepareStatement("insert into test values(?)");
Random random = new Random(System.currentTimeMillis());
timer.start();
for (int i = 0; i < transactions; i++) {
for (int j = 0; j < insertsPerTransaction; j++) {
insert.setInt(1, random.nextInt());
try {
insert.executeUpdate();
} catch (SQLException e) {
System.out.println("Collision!");
}
}
connection.commit();
timer.stop();
report("Transaction " + i);
timer.start();
}
}
private void report(String label)
{
System.out.println(label+": "+timer.msec());
}
private void connectToDB() throws ClassNotFoundException, InstantiationException, IllegalAccessException,
SQLException
{
driver = (Driver) Class.forName("org.postgresql.Driver").newInstance();
connection = DriverManager.getConnection("jdbc:postgresql:ris", "ris", "ris");
connection.setAutoCommit(false);
statement = connection.createStatement();
}
private void sql(String sql)
{
try {
statement.execute(sql);
} catch (SQLException e) {
ExceptionPrinter.print(e);
}
}
private InsertPerformance(String[] args)
{
int a = 0;
insertsPerTransaction = Integer.parseInt(args[a++]);
transactions = Integer.parseInt(args[a++]);
System.out.println("Inserts per transaction: " + insertsPerTransaction);
System.out.println("Transactions: " + transactions);
}
private Driver driver;
private Connection connection;
private Statement statement;
private int insertsPerTransaction;
private int transactions;
private Stopwatch timer = new Stopwatch();
}
