You'll Never Guess What Was Causing RSpec to output "Time: 0.1234 ms"

psqlrc.md

When running specs I often see this output before the specs start to run.

> rspec spec
Time: 0.288 ms
Time: 0.110 ms
Time: 0.084 ms
Time: 0.095 ms
Time: 0.105 ms
Time: 0.115 ms
Time: 0.256 ms
Time: 0.559 ms
Time: 14.818 ms
Time: 0.433 ms
..............................................................................................................................................................................

Conditions:

1. Rails 4.*
2. PostgreSQL
3. using db/structure.sql, not db/schema.rb
4. \timing set, in ~/.psqlrc

Apparently this is happening to approximately zero other people out there, as I could find no mentions of it. I assumed it was rspec outputting the time it look to load either the specs or the files under test. It turns out, however, that while running specs rake db:structure:load gets run, which loads structure.sql using the psql command line tool. It turns out, "Timing" gets output to STDERR and can apparently not be quieted.

# /activerecord/lib/active_record/tasks/postgresql_database_tasks.rb#L62
def structure_load(filename)
  set_psql_env
  Kernel.system("psql -q -f #{Shellwords.escape(filename)} #{configuration['database']}")
end

rails source

Possible Solution: Use psql --command to load structure.sql, which will ignore ~/.psqlrc

Potential downsides to ignoring people's .psqlrc? Would piping the command into psql be cross platform?

UPDATE: Setting \set QUIET 1 does not surppress the timing output. Per twitter convo with @gabebw.

Thanks, this just happened to me over the past 24 hours after I'd started to tinker with my own .psqlrc. I didn't realize that the db:structure:load and db:test:prepare actually was starting an interactive session until I saw my little boilerplate fly-by during their execution.