Saving new domain objects leads to a immediate flush

Saving a newly created domain object (in a controller) leads to a immediate flush of the hibernate session. (I added the sleep() to be sure that it's not a logging issue and i double checked with mysql-query.log that these calls are made and not only "printed")

5.times { i ->
        new Foo(bar: "$i").save()
        log.error("$i")
        sleep(1000)
}

with hibernate query log enabled this leads to

2013-12-11 15:26:41,593 [http-bio-8080-exec-6] DEBUG hibernate.SQL  - insert into foo (version, bar) values (?, ?)
| Error 2013-12-11 15:26:41,596 [http-bio-8080-exec-6] ERROR app.HomeController  - 0
2013-12-11 15:26:42,600 [http-bio-8080-exec-6] DEBUG hibernate.SQL  - insert into foo (version, bar) values (?, ?)
| Error 2013-12-11 15:26:42,605 [http-bio-8080-exec-6] ERROR app.HomeController  - 1
2013-12-11 15:26:43,610 [http-bio-8080-exec-6] DEBUG hibernate.SQL  - insert into foo  (version, bar) values (?, ?)
| Error 2013-12-11 15:26:43,613 [http-bio-8080-exec-6] ERROR app.HomeController  - 2
2013-12-11 15:26:44,618 [http-bio-8080-exec-6] DEBUG hibernate.SQL  - insert into foo (version, bar) values (?, ?)
| Error 2013-12-11 15:26:44,622 [http-bio-8080-exec-6] ERROR app.HomeController  - 3
2013-12-11 15:26:45,626 [http-bio-8080-exec-6] DEBUG hibernate.SQL  - insert into foo (version, bar) values (?, ?)
| Error 2013-12-11 15:26:45,631 [http-bio-8080-exec-6] ERROR app.HomeController  - 4

looking at the grails documentation at http://grails.org/doc/latest/ref/Domain%20Classes/save.html

The save method informs the persistence context that an instance should be saved or updated. The object will not be persisted immediately unless the flush argument is used:

The question for me is: Is the documentation just wrong or is this a bug?

The problem (at least for me) is that the complete session is flushed which may lead to unwanted changes being persisted.

I reproduced this on grails-2.3.3 and grails-2.2.4 and checked with latest hibernate3 and hibernate4 plugins. The behaviour is the same for all configuration combinations so i guess this is a misleading documentation but still i wanted to double check.

Update

As requested by sergio this super simple controller leads to the output above.

class HomeController {
 def index(){
  5.times { i ->
   new Foo(bar: "$i").save()
   log.error("$i")
   sleep(1000)
  }
 }  
}

Solution

You're not seeing a flush, just earlier SQL than you expect. This is splitting hairs a bit since you're seeing earlier database activity than you'd expect, but there's no explicit flush until the end of the request - you can see that in a debugger or with logging enabled.

What you're seeing is that Hibernate needs to perform the insert in order to retrieve the autogenerated id. So it is doing an explicit insert for each save() call, but there's only one real flush at the end of the request, triggered by the OpenSessionInView interceptor.

So the docs are a bit off. Calling save() on a new non-persistent instance will trigger a database insert, but no flush. Calling save() on a modified persistent instance or calling delete() on a persistent instance will not trigger a database update until an explicit flush, or Hibernate detecting that it needs to, e.g. if you do a query, since that could be affected by unflushed data.

EDIT

Here's a bigger example to show what's going on. First I create 2 Foos and flush those saves. Then I edit and save one and delete another, both without a flush. I do the same creation of 5 new instances and see their SQL, but none for the update or delete because there's no flush yet. At the end when I do an explicit flush you do see those two SQL statements:

class HomeController {

   def index() {

      def toEdit = new Foo(bar: 'editme').save()
      def toDelete = new Foo(bar: 'deleteme').save(flush: true)
      println 'created first 2 and flushed'

      toEdit.bar += '_edited'
      toEdit.save()
      toDelete.delete()
      println 'edited one, deleted one'

      5.times { i ->
         new Foo(bar: "$i").save()
         println "created foo $i"
         sleep 1000
      }
      println "created 5"

      println "before explicit flush"
      Foo.withSession { it.flush() }
      println "after explicit flush"
   }  
}

and here's the output:

2013-12-11 12:46:20,120 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
2013-12-11 12:46:20,138 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
created first 2 and flushed
edited one, deleted one
2013-12-11 12:46:20,188 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
created foo 0
2013-12-11 12:46:21,197 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
created foo 1
2013-12-11 12:46:22,202 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
created foo 2
2013-12-11 12:46:23,211 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
created foo 3
2013-12-11 12:46:24,219 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - insert into foo (id, version, bar) values (null, ?, ?)
created foo 4
created 5
before explicit flush
2013-12-11 12:46:25,282 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - update foo set version=?, bar=? where id=? and version=?
2013-12-11 12:46:25,284 [http-bio-9090-exec-1] DEBUG hibernate.SQL  - delete from foo where id=? and version=?
after explicit flush