Skip to content

Instantly share code, notes, and snippets.

@mariovisic
Last active December 23, 2015 19:19
Show Gist options
  • Save mariovisic/6681559 to your computer and use it in GitHub Desktop.
Save mariovisic/6681559 to your computer and use it in GitHub Desktop.
Postgres rails bug testing

Hi everyone

I'm trying to hunt down a bug with rails and postgres related to timestamps rounding to the nearest second. To help could you please run this on your rails app. All that's required is a model that has a created_at timestamp and at least one record in the database, you can change the first line of the script to something that fits.

Please comment with your results.

Here's an attempt at a description of the bug: One some machines, when database records are converted to active record objects, the decimal precision is completely lost from timestamps. When we query the database using one of these timestamps, the fractions of a second are included in the SQL, this means that the database query will take into account the incorrect subsecond value of the record, so instead of something like this:

SELECT COUNT(*) FROM "users" WHERE (created_at > '2013-09-16 06:31:33.912670')

You get this:

SELECT COUNT(*) FROM "users" WHERE (created_at > '2013-09-16 06:31:33.000000')

This would not be a problem at all if the subseconds were left off completely like so:

SELECT COUNT(*) FROM "users" WHERE (created_at > '2013-09-16 06:31:33')

But alas they are included.

Here are my results for the test from one machine that shows the bug. My work machine has a very similar setup and does not show the bug. Also some co-workers machines show the bug while others don't.

Bug present?: true
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.3.0]
Raw SQL:      2013-03-23 10:01:58.302891
AR Timestamp: 1364032918.0
Rails:        4.0.0
PG Gem:       0.17.0 Revision: 7cdff0a462e5 
Postgres:     psql (PostgreSQL) 9.3.0

On another project, same machine:

Bug present?: true
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.3.0]
Raw SQL:      2013-09-24 09:32:33.553674
AR Timestamp: 1380015153.0
Rails:        3.2.13
PG Gem:       0.15.1 Revision: 0bfb6ff650be 
Postgres:     psql (PostgreSQL) 9.3.0

Cheers Mario

model = User # For the test we just need any active record model that has a created_at timestamp.
puts %{
==========================
Bug present?: #{model.where('created_at > ?', model.last.created_at).any?}
Ruby: #{RUBY_DESCRIPTION}
Raw SQL: #{ActiveRecord::Base.connection.execute(model.where('created_at > ?', Time.at(model.last.created_at.to_i)).to_sql).to_a.first['created_at']}
AR Timestamp: #{model.last.created_at.to_f}
Rails: #{Rails.version}
PG Gem: #{PG::VERSION} #{PG::REVISION}
Postgres: #{`psql --version`}
==========================
}
@pat
Copy link

pat commented Sep 24, 2013

Two apps (one on Ruby 1.9.3, one on 2.0.0)

==========================

Bug present?: false
Ruby:         ruby 2.0.0p195 (2013-05-14 revision 40734) [x86_64-darwin11.4.2]
Raw SQL:      2013-09-16 00:18:56.296222
AR Timestamp: 1379290736.296222
PG Gem:       0.15.1 Revision: 0bfb6ff650be
Postgres:     psql (PostgreSQL) 9.2.2


==========================
==========================

Bug present?: false
Ruby:         ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-darwin11.4.2]
Raw SQL:      2013-09-11 00:43:29.049969
AR Timestamp: 1378860209.049969
PG Gem:       0.15.1 Revision: 0bfb6ff650be
Postgres:     psql (PostgreSQL) 9.2.2


==========================

@markcipolla
Copy link

==========================

Bug present?: false
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.4.0]
Raw SQL:      2013-09-23 22:50:28.514101
AR Timestamp: 1379976628.514101
Rails:        3.2.14
PG Gem:       0.17.0 Revision: 7cdff0a462e5
Postgres:     psql (PostgreSQL) 9.2.1


==========================

@EdwardTippett
Copy link

==========================

Bug present?: false
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.4.0]
Raw SQL:      2013-09-24 05:08:10.808892
AR Timestamp: 1379999290.808892
Rails:        3.2.14
PG Gem:       0.17.0 Revision: 7cdff0a462e5
Postgres:     psql (PostgreSQL) 9.3.0


==========================

@pjg
Copy link

pjg commented Sep 24, 2013

D, [2013-09-24T11:11:10.235476 #11656] DEBUG -- :   User Load (3.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
D, [2013-09-24T11:11:10.316235 #11656] DEBUG -- :    (2.1ms)  SELECT COUNT(*) FROM "users" WHERE (created_at > '2013-07-19 19:08:44.579721')
D, [2013-09-24T11:11:10.317440 #11656] DEBUG -- :   User Load (0.5ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
D, [2013-09-24T11:11:10.318835 #11656] DEBUG -- :    (0.4ms)  SELECT "users".* FROM "users" WHERE (created_at > '2013-07-19 19:08:44.000000')
D, [2013-09-24T11:11:10.319749 #11656] DEBUG -- :   User Load (0.5ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1

==========================

Bug present?: false
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-linux]
Raw SQL:      2013-07-19 19:08:44.579721
AR Timestamp: 1374260924.579721
Rails:        4.0.0
PG Gem:       0.16.0 Revision: 4e0606f5f5aa 
Postgres:     psql (PostgreSQL) 9.1.9
contains support for command-line editing

@marekstachura
Copy link

==========================

Bug present?: false
Ruby:         ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-linux]
Raw SQL:      2013-09-24 06:41:02.005457
AR Timestamp: 1380004862.005457
Rails:        3.2.14
PG Gem:       0.16.0 Revision: 4e0606f5f5aa
Postgres:     psql (PostgreSQL) 9.2.2

==========================

@prakashmurthy
Copy link

==========================

Bug present?: false
Ruby:         ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-darwin12.2.0]
Raw SQL:      2013-05-07 00:18:22.832752
AR Timestamp: 1367885902.8327522
Rails:        3.2.11
PG Gem:       0.14.1 Revision: ef533f731814 
Postgres:     psql (PostgreSQL) 9.1.9
contains support for command-line editing


==========================

@jmartelletti
Copy link

==========================

Bug present?: false
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [i686-linux]
Raw SQL:      2013-09-07 08:45:13.018894
AR Timestamp: 1378543513.0188942
Rails:        4.0.0
PG Gem:       0.16.0 Revision: 4e0606f5f5aa
Postgres:     psql (PostgreSQL) 9.3beta2

==========================

@BRMatt
Copy link

BRMatt commented Sep 24, 2013

Desktop:

==========================                                              

Bug present?: false                                                     
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-linux] 
Raw SQL:      2013-09-18 08:17:00.331207                                
AR Timestamp: 1379492220.3312068                                        
Rails:        3.2.14                                                    
PG Gem:       0.14.1 Revision: ef533f731814                             
Postgres:     psql (PostgreSQL) 9.1.9                                   
contains support for command-line editing                               


==========================                                              

Heroku:

==========================                                              

Bug present?: false                                                     
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-linux] 
Raw SQL:      2013-09-23 03:47:54.143411                                
AR Timestamp: 1379908074.143411                                         
Rails:        3.2.14                                                    
PG Gem:       0.14.1 Revision: ef533f731814                             
Postgres:                                                               

==========================                                              

@fourseven
Copy link

Laptop

==========================

Bug present?: false
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.5.0]
Raw SQL:      2013-09-24 02:47:17.90719
AR Timestamp: 1379990837.90719
Rails:        4.0.0
PG Gem:       0.16.0 Revision: 4e0606f5f5aa
Postgres:     psql (PostgreSQL) 9.3.0


==========================

One of our server deployments (different app)

==========================

Bug present?: false
Ruby:         ruby 1.9.2p290 (2011-07-09 revision 32553) [i686-linux]
Raw SQL:      2013-09-23 20:30:27.064831
AR Timestamp: 1379968227.064831
Rails:        3.2.14
PG Gem:       0.13.1 Revision: 1ba641824000
Postgres:     psql (PostgreSQL) 8.4.14
contains support for command-line editing


==========================

@sricho
Copy link

sricho commented Sep 25, 2013

Local development machine

Bug present?: true
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.3.0]
Raw SQL:      2013-09-24 04:56:57.24671
AR Timestamp: 1379998617.0
Rails:        3.2.14
PG Gem:       0.17.0 Revision: 7cdff0a462e5
Postgres:     psql (PostgreSQL) 9.2.4

@parndt
Copy link

parndt commented Sep 25, 2013

Development machine

Bug present?: false
Ruby: ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin13.0.0]
Raw SQL: 2013-09-23 22:19:40.146921
AR Timestamp: 1379974780.146921
Rails: 4.0.0
PG Gem: 0.17.0 Revision: 7cdff0a462e5
Postgres: psql (PostgreSQL) 9.3.0

@mattallen
Copy link

Bug present?: false
Ruby: ruby 2.0.0p195 (2013-05-14 revision 40734) [x86_64-darwin12.2.0]
Raw SQL: 2013-09-16 06:20:59.85067
AR Timestamp: 1379312459.85067
Rails: 4.0.0.rc2
PG Gem: 0.15.1 Revision: 0bfb6ff650be
Postgres: psql (PostgreSQL) 9.1.3
contains support for command-line editing

@JonRowe
Copy link

JonRowe commented Sep 25, 2013

Locally

Bug present?: true
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.4.0]
Raw SQL:      2013-04-08 07:16:56
AR Timestamp: 1365387515.0
Rails:        3.2.11
PG Gem:       0.15.1 Revision: 0bfb6ff650be
Postgres:     psql (PostgreSQL) 9.2.4

Heroku

Bug present?: true
Ruby:         ruby 1.9.2p320 (2012-04-20 revision 35421) [x86_64-linux]
Raw SQL:      2013-04-08 07:16:56
AR Timestamp: 1365387515.0
Rails:        3.2.11
PG Gem:       0.15.1 Revision: 0bfb6ff650be
Postgres:

@lcpriest
Copy link

Dev Machine

==========================

Bug present?: true
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.3.0]
Raw SQL:      2013-09-25 00:27:34.570972
AR Timestamp: 1380068854.0
Rails:        4.0.0
PG Gem:       0.17.0 Revision: 7cdff0a462e5
Postgres:     psql (PostgreSQL) 9.2.4


==========================

@seanarnold
Copy link

Bug present?: false
Ruby: ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin12.3.0]
Raw SQL: 2013-08-21 15:30:35.854908
AR Timestamp: 1377055835.854908
Rails: 3.2.13
PG Gem: 0.14.1 Revision: ef533f731814
Postgres: psql (PostgreSQL) 9.2.4

@benhoskings
Copy link

User Load (1.1ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
 (31.4ms)  SELECT COUNT(*) FROM "users" WHERE (created_at > '2013-09-05 05:56:29.816022')
User Load (0.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
 (32.6ms)  SELECT "users".* FROM "users" WHERE (created_at > '2013-09-05 05:56:29.000000')
User Load (0.5ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
Bug present?: false
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.4.0]
Raw SQL:      2013-09-05 05:56:29.816022
AR Timestamp: 1378360589.816022
Rails:        3.2.14
PG Gem:       0.17.0 Revision: 7cdff0a462e5
Postgres:     psql (PostgreSQL) 9.3.0

@lengarvey
Copy link

==========================

Bug present?: false
Ruby:         ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-darwin12.3.0]
Raw SQL:      2013-09-11 06:19:42.859682
AR Timestamp: 1378880382.859682
Rails:        3.2.14
PG Gem:       0.14.0 Revision: a3a3177b921c
Postgres:     psql (PostgreSQL) 9.2.4


==========================

@seanarnold
Copy link

Bug present?: false
Ruby: ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-darwin12.2.1]
Raw SQL: 2013-07-03 12:17:47.974251
AR Timestamp: 1372810667.974251
Rails: 3.2.13
PG Gem: 0.14.1 Revision: ef533f731814
Postgres: psql (PostgreSQL) 9.2.4

@steveh
Copy link

steveh commented Sep 25, 2013

Bug present?: false
Ruby: ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.4.0]
Raw SQL: 2013-09-25 01:06:42.260137
AR Timestamp: 1380071202.2601368
Rails: 4.0.0
PG Gem: 0.17.0 Revision: 7cdff0a462e5
Postgres: psql (PostgreSQL) 9.2.4

@freshtonic
Copy link

Bug present?: false
Ruby: ruby 1.9.3p385 (2013-02-06 revision 39114) [x86_64-darwin12.5.0]
Raw SQL: 2013-09-17 12:21:46.587274
AR Timestamp: 1379420506.587274
Rails: 3.2.13
PG Gem: 0.15.1 Revision: 0bfb6ff650be
Postgres: psql (PostgreSQL) 9.2.4

@tenderlove
Copy link

You should probably post the table schema. I'm guessing the column type is different among the people on here.

@mariovisic
Copy link
Author

@tenderlove on two different machines on the same project (one showing the bug and another not showing it) the column info for the created_at are identical. Very strange.

Postgres:

select * from information_schema.columns  where table_name = 'users' and column_name = 'created_at';

-[ RECORD 1 ]------------+----------------------------
table_catalog            | microlancer_development
table_schema             | public
table_name               | users
column_name              | created_at
ordinal_position         | 5
column_default           |
is_nullable              | NO
data_type                | timestamp without time zone
character_maximum_length |
character_octet_length   |
numeric_precision        |
numeric_precision_radix  |
numeric_scale            |
datetime_precision       | 6
interval_type            |
interval_precision       |
character_set_catalog    |
character_set_schema     |
character_set_name       |
collation_catalog        |
collation_schema         |
collation_name           |
domain_catalog           |
domain_schema            |
domain_name              |
udt_catalog              | microlancer_development
udt_schema               | pg_catalog
udt_name                 | timestamp
scope_catalog            |
scope_schema             |
scope_name               |
maximum_cardinality      |
dtd_identifier           | 5
is_self_referencing      | NO
is_identity              | NO
identity_generation      |
identity_start           |
identity_increment       |
identity_maximum         |
identity_minimum         |
identity_cycle           |
is_generated             | NEVER
generation_expression    |
is_updatable             | YES

Rails:

create_table "users", :force => true do |t|
  t.datetime "created_at",                                                                         :null => false
end

@mariovisic
Copy link
Author

When the record is created the timestamp has the fractions, when it gets reloaded from the DB they get lost, eg:

user = User.create(...)
user.created_at.to_f        # => 1380082444.440707
user.reload.created_at.to_f # => 1380082444.0

Also when you query the database directly not using a model it has the fractions:

sql = 'SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1'
Time.parse(ActiveRecord::Base.connection.execute(sql).to_a.first['created_at']).to_f 
#=> 1380082444.440707

@shime
Copy link

shime commented Sep 25, 2013

==========================
Bug present?: false
Ruby: ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-linux]
Raw SQL: 2013-09-24 08:11:44.936302
AR Timestamp: 1380010304.9363022
Rails: 4.0.0
PG Gem: 0.16.0 Revision: 4e0606f5f5aa 
Postgres: psql (PostgreSQL) 9.1.9
contains support for command-line editing

==========================

@glebm
Copy link

glebm commented Sep 25, 2013

  User Load (4.3ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
   (1.1ms)  SELECT COUNT(*) FROM "users" WHERE (created_at > '2013-09-18 07:36:00.000000')
  User Load (0.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1
   (0.5ms)  SELECT "users".* FROM "users" WHERE (created_at > '2013-09-18 07:36:00.000000')
  User Load (0.5ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT 1

==========================

Bug present?: true
Ruby:         ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-darwin12.3.0]
Raw SQL:      2013-09-18 07:36:00.15242
AR Timestamp: 1379489760.0
Rails:        4.0.0
PG Gem:       0.17.0 Revision: 7cdff0a462e5
Postgres:     psql (PostgreSQL) 9.3.0


==========================

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment