Previously, newly merged Ceilometer code broke my test to throw a sorting error when there is no index. After jd's patch "Change Ia2ff201c: Disable mongod prealloc, wait for it to start" was merged (+ possibly other changes), seems like my test is working again. If I make the test database 12000 times larger, I don't get any sorting error. The t…

no-sort-error-database-x-12000.txt

$ tox -e py27 -- tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order
GLOB sdist-make: /opt/stack/ceilometer/setup.py
py27 inst-nodeps: /opt/stack/ceilometer/.tox/dist/ceilometer-2013.2.a263.g33b691f.zip
py27 runtests: commands[0] | bash -x /opt/stack/ceilometer/run-tests.sh tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order
WARNING:test command found but not installed in testenv
  cmd: /bin/bash
  env: /opt/stack/ceilometer/.tox/py27
Maybe forgot to specify a dependency?
+ set -e
+ '[' tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order = --coverage ']'
+ '[' '!' '' ']'
+ bash tools/init_testr_if_needed.sh
+ python setup.py testr --slowest '--testr-args=--concurrency=1 --here=nova_tests tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order'
running testr
running=${PYTHON:-python} -m subunit.run discover -t ./nova_tests ./nova_tests --list 
PASSED (id=71)
Slowest Tests
Test id                                                                          Runtime (s)
-------------------------------------------------------------------------------  -----------
tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order  265.190
++ mktemp -d
+ MONGO_DATA=/tmp/tmp.dOuBJgQw5X
+ trap clean_exit EXIT
+ mkfifo /tmp/tmp.dOuBJgQw5X/out
+ MONGO_PID=13695
+ mongod --maxConns 32 --noprealloc --smallfiles --quiet --noauth --port 29000 --dbpath /tmp/tmp.dOuBJgQw5X --bind_ip localhost
+ read line
+ echo 'note: noprealloc may hurt performance in many applications'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:21:39.725 [initandlisten] MongoDB starting : pid=13695 port=29000 dbpath=/tmp/tmp.dOuBJgQw5X 64-bit host=precise64'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:21:39.735 [initandlisten] db version v2.4.5'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:21:39.759 [initandlisten] git version: a2ddc68ba7c9cee17bfe69ed840383ec3506602b'
+ read line
+ echo 'Wed Jul 24 05:21:39.759 [initandlisten] build info: Linux ip-10-2-29-40 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_49'
+ read line
+ echo 'Wed Jul 24 05:21:39.759 [initandlisten] allocator: tcmalloc'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:39.759 [initandlisten] options: { bind_ip: "localhost", dbpath: "/tmp/tmp.dOuBJgQw5X", maxConns: 32, noauth: true, noprealloc: true, port: 29000, quiet: true, smallfiles: true }'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:39.914 [initandlisten] journal dir=/tmp/tmp.dOuBJgQw5X/journal'
+ read line
+ echo 'Wed Jul 24 05:21:39.915 [initandlisten] recover : no journal files present, no recovery needed'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:41.030 [initandlisten] preallocateIsFaster=true 21.38'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:41.485 [initandlisten] preallocateIsFaster=true 7.8'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:43.007 [initandlisten] preallocateIsFaster=true 9.22'
+ read line
+ echo 'Wed Jul 24 05:21:43.007 [initandlisten] preallocateIsFaster check took 3.091 secs'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:43.007 [initandlisten] preallocating a journal file /tmp/tmp.dOuBJgQw5X/journal/prealloc.0'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:43.481 [initandlisten] preallocating a journal file /tmp/tmp.dOuBJgQw5X/journal/prealloc.1'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:43.811 [initandlisten] preallocating a journal file /tmp/tmp.dOuBJgQw5X/journal/prealloc.2'
+ read line
+ echo 'Wed Jul 24 05:21:44.142 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/local.ns, filling with zeroes...'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:21:44.142 [FileAllocator] creating directory /tmp/tmp.dOuBJgQw5X/_tmp'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:21:44.147 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/local.ns, size: 16MB,  took 0.002 secs'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:44.149 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/local.0, filling with zeroes...'
+ read line
+ echo 'Wed Jul 24 05:21:44.150 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/local.0, size: 16MB,  took 0.001 secs'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:21:44.167 [initandlisten] waiting for connections on port 29000'
+ break
+ cat /tmp/tmp.dOuBJgQw5X/out
+ export CEILOMETER_TEST_MONGODB_URL=mongodb://localhost:29000/ceilometer
+ CEILOMETER_TEST_MONGODB_URL=mongodb://localhost:29000/ceilometer
+ python setup.py testr --slowest '--testr-args=--concurrency=1 tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order'
Wed Jul 24 05:21:44.167 [websvr] admin web console waiting for connections on port 30000
running testr
Wed Jul 24 05:21:48.947 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.ns, filling with zeroes...
Wed Jul 24 05:21:48.954 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.ns, size: 16MB,  took 0.006 secs
Wed Jul 24 05:21:48.955 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.0, filling with zeroes...
Wed Jul 24 05:21:48.956 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.0, size: 16MB,  took 0.001 secs
Wed Jul 24 05:21:48.969 [conn1] build index ceilometer.resource { _id: 1 }
Wed Jul 24 05:21:48.975 [conn1] build index done.  scanned 0 total records. 0.005 secs
Wed Jul 24 05:21:48.975 [conn1] info: creating collection ceilometer.resource on add index
Wed Jul 24 05:21:48.975 [conn1] build index ceilometer.resource { user_id: 1, source: 1 }
Wed Jul 24 05:21:48.978 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:21:48.983 [conn1] build index ceilometer.meter { _id: 1 }
Wed Jul 24 05:21:48.986 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:21:48.986 [conn1] info: creating collection ceilometer.meter on add index
Wed Jul 24 05:21:48.986 [conn1] build index ceilometer.meter { resource_id: 1, user_id: 1, counter_name: 1, timestamp: 1, source: 1 }
Wed Jul 24 05:21:48.990 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:21:48.998 [conn1] dropDatabase ceilometer starting
Wed Jul 24 05:21:49.031 [conn1] removeJournalFiles
Wed Jul 24 05:21:49.044 [conn1] dropDatabase ceilometer finished
Wed Jul 24 05:21:49.047 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.ns, filling with zeroes...
Wed Jul 24 05:21:49.049 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.ns, size: 16MB,  took 0.002 secs
Wed Jul 24 05:21:49.050 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.0, filling with zeroes...
Wed Jul 24 05:21:49.053 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.0, size: 16MB,  took 0.002 secs
Wed Jul 24 05:21:49.070 [conn1] build index ceilometer.resource { _id: 1 }
Wed Jul 24 05:21:49.073 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:21:49.074 [conn1] info: creating collection ceilometer.resource on add index
Wed Jul 24 05:21:49.074 [conn1] build index ceilometer.resource { user_id: 1, source: 1 }
Wed Jul 24 05:21:49.077 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:21:49.080 [conn1] build index ceilometer.meter { _id: 1 }
Wed Jul 24 05:21:49.084 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:21:49.084 [conn1] info: creating collection ceilometer.meter on add index
Wed Jul 24 05:21:49.084 [conn1] build index ceilometer.meter { resource_id: 1, user_id: 1, counter_name: 1, timestamp: 1, source: 1 }
Wed Jul 24 05:21:49.087 [conn1] build index done.  scanned 0 total records. 0.002 secs
Wed Jul 24 05:21:49.116 [conn1] build index ceilometer.user { _id: 1 }
Wed Jul 24 05:21:49.118 [conn1] build index done.  scanned 0 total records. 0.001 secs
Wed Jul 24 05:21:49.121 [conn1] build index ceilometer.project { _id: 1 }
Wed Jul 24 05:21:49.121 [conn1] build index done.  scanned 0 total records. 0 secs
Wed Jul 24 05:22:13.677 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.1, filling with zeroes...
Wed Jul 24 05:22:13.681 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.1, size: 32MB,  took 0.002 secs
Wed Jul 24 05:22:44.128 [conn1] update ceilometer.project query: { _id: "project-id-13111" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:85 230ms
Wed Jul 24 05:23:09.799 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.2, filling with zeroes...
Wed Jul 24 05:23:09.803 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.2, size: 64MB,  took 0.003 secs
Wed Jul 24 05:23:25.858 [conn1] update ceilometer.user query: { _id: "user-id-22919" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:119 101ms
Wed Jul 24 05:23:44.194 [conn1] update ceilometer.user query: { _id: "user-id-27409" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:68 282ms
Wed Jul 24 05:24:58.061 [FileAllocator] allocating new datafile /tmp/tmp.dOuBJgQw5X/ceilometer.3, filling with zeroes...
Wed Jul 24 05:24:58.072 [FileAllocator] done allocating datafile /tmp/tmp.dOuBJgQw5X/ceilometer.3, size: 128MB,  took 0.009 secs
Wed Jul 24 05:25:44.310 [conn1] update ceilometer.project query: { _id: "project-id-56879" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:67 174ms
Wed Jul 24 05:25:59.477 [conn1] query ceilometer.meter query: { $query: {}, $orderby: { timestamp: -1 } } ntoreturn:0 ntoskip:0 nscanned:60005 scanAndOrder:1 keyUpdates:0 numYields: 1 locks(micros) r:1475879 nreturned:60005 reslen:27917923 1391ms
running=${PYTHON:-python} -m subunit.run discover -t ./ ./tests --list 
running=${PYTHON:-python} -m subunit.run discover -t ./ ./tests  --load-list /tmp/tmpnS45dc
Ran 2 (+1) tests in 256.870s (-8.320s)
PASSED (id=69)
Slowest Tests
Test id                                                                          Runtime (s)
-------------------------------------------------------------------------------  -----------
tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order  256.869
+ clean_exit
+ local error_code=0
+ rm -rf /tmp/tmp.dOuBJgQw5X
+ '[' 13695 ']'
+ kill -9 13695
+ return 0
py27 runtests: commands[1] | /opt/stack/ceilometer/tools/conf/check_uptodate.sh
___________________________________ summary ____________________________________
  py27: commands succeeded
  congratulations :)