Inserts get slower as table gets bigger - Mailing list pgsql-general

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();
}