Gorm: The performance for update is bad!

[zj8487]

I test a update as follow:

    start := time.Now()
    if val, ok := value.(*data); ok {
        ps.Model(val.Model).Updates(val.Data)
    }
    fmt.Printf("111111111111111111The time save take:%v\n", time.Since(start))

The sql take just 1.83 ms.

[2015-12-28 21:48:58]  [1.83ms]  UPDATE `profile` SET `nick_name` = 'xxx', `exchanged_times` = '0', `exchanged_for_other_currency` = '0', `gem` = '0', `currency` = '100', `contact` = '', `purchased_for_othertimes` = '0', `max_gem` = '0', `signature` = '', `is_active` = 'true', `charged_times` = '0', `purchased_gem` = '0', `exchanged_for_othertimes` = '0', `purchased_times` = '0', `gender` = '0', `charged_for_othertimes` = '0', `charged_for_other_money` = '0', `charged_money` = '0', `exchanged_currency` = '0', `purchased_for_other_gem` = '0', `max_currency` = '100', `privilege_end_time` = '1984-08-07T07:45:00+08:00', `taked_currency` = '0', `avatar_url` = '5', `privilege_level` = '0', `bank_currency` = '0', `created_at` = '2015-12-28T21:48:57+08:00'  WHERE (`player_id` = '1024')

but the ps.Model(val.Model).Updates(val.Data) take 41ms.

111111111111111111The time save take:41.247981ms

why? and how to refine?
@jinzhu

[jinzhu]

Please follow https://github.com/jinzhu/gorm/blob/master/CONTRIBUTING.md to submit a runnable script let me check.

In projects I have written, I think the performance is pretty fine.

[zj8487]

Thanks your feedback, i will submit a script later.

[zj8487]

Hi, @jinzhu
The test script is as follow:
I test the updates and save all of them are same.

package main

import (
    "fmt"
    "time"

    "github.com/fatih/structs"
    _ "github.com/go-sql-driver/mysql"
    "github.com/jinzhu/gorm"
)

var (
    driver = "mysql"
    cons   = "root:yourpwd@/test?charset=utf8&parseTime=True&loc=Local"
)

type TestTable struct {
    PlayerId  uint64 `gorm:"primary_key"`
    NickName  string `sql:"type:varchar(50)"`
    AvatarUrl string `sql:"type:varchar(50)"`
    Signature string `sql:"type:varchar(50)"`
    Contact   string `sql:"type:varchar(50)"`
    Gender    uint32 `sql:"not null; default:0"`
    IsActive  bool   `sql:"not null; default:1"`

    PrivilegeLevel   uint64    `sql:"not null; default:0"`
    PrivilegeEndTime time.Time `sql:"DEFAULT: '1984-8-7 07:45:00'"`

    ChargedTimes              uint64 `sql:"not null; default:0"`
    ChargedMoney              uint64 `sql:"not null; default:0"`
    PurchasedTimes            uint64 `sql:"not null; default:0"`
    PurchasedGem              uint64 `sql:"not null; default:0"`
    ExchangedTimes            uint64 `sql:"not null; default:0"`
    ExchangedCurrency         uint64 `sql:"not null; default:0"`
    ChargedForOthertimes      uint64 `sql:"not null; default:0"`
    ChargedForOtherMoney      uint64 `sql:"not null; default:0"`
    PurchasedForOthertimes    uint64 `sql:"not null; default:0"`
    PurchasedForOtherGem      uint64 `sql:"not null; default:0"`
    ExchangedForOthertimes    uint64 `sql:"not null; default:0"`
    ExchangedForOtherCurrency uint64 `sql:"not null; default:0"`

    Gem           uint64 `sql:"not null; default:0"`
    MaxGem        uint64 `sql:"not null; default:0"`
    Currency      uint64 `sql:"not null; default:0"`
    MaxCurrency   uint64 `sql:"not null; default:0"`
    BankCurrency  uint64 `sql:"not null; default:0"`
    TakedCurrency uint64 `sql:"not null; default:0"`

    CreatedAt time.Time
}

type saveData struct {
    Model interface{}
    Data  map[string]interface{}
    Key   uint64
}

type ORM struct {
    *gorm.DB
}

func NewORM(dirver string, args string, maxIdleConns int, maxOpenConns int, enableLog bool) (*ORM, error) {
    db, err := gorm.Open(dirver, args)
    if err != nil {
        return nil, err
    }

    db.SingularTable(true)
    db.LogMode(enableLog)
    db.DB().Ping()
    db.DB().SetMaxIdleConns(maxIdleConns)
    db.DB().SetMaxOpenConns(maxOpenConns)
    o := &ORM{}
    o.DB = db
    return o, nil
}

func (o *ORM) Save1(value interface{}) (err error) {
    start := time.Now()
    if val, ok := value.(*saveData); ok {
        o.Model(val.Model).Updates(val.Data)
        //o.Save(val.Model)
    }
    fmt.Printf("========================The time save take:%v\n", time.Since(start))
    return nil
}

func (o *ORM) Migrate() {
    fmt.Print("running settlement auto migrations...")
    o.AutoMigrate(&TestTable{})
    fmt.Printf("settlement auto migration done \n")
}

func (o *ORM) DropAllTable() error {
    models := []interface{}{&TestTable{}}
    for _, table := range models {
        o.DropTableIfExists(table)
    }
    return nil
}

func (o *ORM) CreatePlayer(playerId uint64, nickName string, currency uint64, avatarUrl string) error {
    err := o.Create(&TestTable{PlayerId: playerId, NickName: nickName, Currency: currency, MaxCurrency: currency, AvatarUrl: avatarUrl}).Error
    return err
}

func (o *ORM) GetTestTable(playerId uint64) (*TestTable, error) {
    p := &TestTable{}
    d := o.Where(&TestTable{PlayerId: playerId}).First(p)
    if d.Error != nil {
        return nil, d.Error
    }
    return p, nil
}

func main() {
    orm, _ := NewORM(driver, cons, 10, 100, true)
    orm.Migrate()
    start := time.Now()
    _ = orm.CreatePlayer(uint64(1024), "jian", 100, "5")
    fmt.Printf("========================The time Insert take:%v\n", time.Since(start))

    player, _ := orm.GetTestTable(uint64(1024))
    player.NickName = "jian zhao"

    st := structs.New(player)
    sd := &saveData{}
    sd.Model = &TestTable{}
    sd.Key = player.PlayerId
    sd.Data = st.Map()
    orm.Save1(sd)

    orm.DropAllTable()
}

The output

[2015-12-29 10:14:44]  [0.96ms]  UPDATE `test_table` SET `purchased_for_other_gem` = '0', `max_gem` = '0', `taked_currency` = '0', `charged_for_othertimes` = '0', `exchanged_for_othertimes` = '0', `exchanged_for_other_currency` = '0', `exchanged_times` = '0', `gender` = '0', `is_active` = 'true', `purchased_times` = '0', `created_at` = '2015-12-29T10:14:44+08:00', `signature` = '', `charged_times` = '0', `bank_currency` = '0', `currency` = '100', `max_currency` = '100', `privilege_end_time` = '1984-08-07T07:45:00+08:00', `gem` = '0', `purchased_gem` = '0', `exchanged_currency` = '0', `avatar_url` = '5', `contact` = '', `charged_money` = '0', `purchased_for_othertimes` = '0', `nick_name` = 'jian zhao', `privilege_level` = '0', `charged_for_other_money` = '0'  WHERE (`player_id` = '1024')
========================The time save take:34.482729ms

This case is very bad.

[2015-12-29 10:20:52]  [115.32ms]  UPDATE `test_table` SET `purchased_gem` = '0', `charged_for_other_money` = '0', `purchased_for_other_gem` = '0', `nick_name` = 'jian zhao', `max_gem` = '0', `exchanged_for_othertimes` = '0', `max_currency` = '100', `taked_currency` = '0', `exchanged_currency` = '0', `gem` = '0', `is_active` = 'true', `charged_money` = '0', `purchased_times` = '0', `created_at` = '2015-12-29T10:20:51+08:00', `privilege_end_time` = '1984-08-07T07:45:00+08:00', `exchanged_times` = '0', `charged_for_othertimes` = '0', `currency` = '100', `bank_currency` = '0', `signature` = '', `contact` = '', `charged_times` = '0', `purchased_for_othertimes` = '0', `exchanged_for_other_currency` = '0', `avatar_url` = '5', `gender` = '0', `privilege_level` = '0'  WHERE (`player_id` = '1024')
========================The time save take:247.259366ms

[jinzhu]

@zj8487 I always get similar results like, much better than your results.

[zj8487]

It is strange!
my go version is 1.5. what's your version?

go version go1.5 linux/amd64

[jinzhu]

[zj8487]

I test go on 1.5.2

go version go1.5.2 linux/amd64

and the output is nearly same

[2015-12-29 13:40:53]  [2.09ms]  UPDATE `test_table` SET `privilege_end_time` = '1984-08-07T07:45:00+08:00', `max_gem` = '0', `taked_currency` = '0', `nick_name` = 'jian zhao', `purchased_for_other_gem` = '0', `max_currency` = '100', `charged_times` = '0', `charged_money` = '0', `charged_for_othertimes` = '0', `exchanged_for_other_currency` = '0', `gem` = '0', `privilege_level` = '0', `exchanged_currency` = '0', `exchanged_for_othertimes` = '0', `signature` = '', `charged_for_other_money` = '0', `created_at` = '2015-12-29T13:40:53+08:00', `currency` = '100', `bank_currency` = '0', `contact` = '', `exchanged_times` = '0', `is_active` = 'true', `purchased_times` = '0', `purchased_gem` = '0', `purchased_for_othertimes` = '0', `avatar_url` = '5', `gender` = '0'  WHERE (`player_id` = '1024')
========================The time save take:23.853789ms

you are on mac system, if it is possible can you test on unbutu system?

[zj8487]

@jinzhu
I test on several linux system based on go1.5.2 linux/amd64, and the results are nearly same!
is it possible it is performance issue on linux/amd64 version?

[jinzhu]

Not sure, our applications all deployed on linux servers, but don't seems have problem.

But I don't have time to test the script on a linux machine yet, will do it as soon as have time.

Thank you for your report.

[zj8487]

@jinzhu
I test on ubuntu again. there is no changes!
and i update the test script above!
And i found that

i: performance for insert is not good at the same.
ii:every insert or update operation will generate two sql command, is it okay?

(/home/xxx/test.go:103) 
[2016-02-24 09:40:35]  [0.70ms]  INSERT INTO `test_table` (`signature`,`created_at`,`avatar_url`,`nick_name`,`player_id`,`max_currency`,`currency`,`contact`) VALUES ('','2016-02-24T09:40:35+08:00','5','jian','1024','100','100','') 

(/home/xxx/test.go:103) 
[2016-02-24 09:40:35]  [1.01ms]  SELECT  max_gem, bank_currency, taked_currency, gender, charged_times, purchased_gem, exchanged_times, is_active, charged_money, purchased_times, charged_for_othertimes, charged_for_other_money, purchased_for_othertimes, purchased_for_other_gem, exchanged_for_othertimes, exchanged_for_other_currency, gem, exchanged_currency, privilege_level, privilege_end_time FROM `test_table`  WHERE (`player_id` = '1024') ORDER BY `test_table`.`player_id` ASC LIMIT 1
========================The time insert take:43.81883ms

(/home/xxx/test.go:109) 
[2016-02-24 09:40:35]  [2.05ms]  SELECT  * FROM `test_table`  WHERE (`player_id` = '1024') ORDER BY `test_table`.`player_id` ASC LIMIT 1

(/home/xxx/test.go:81) 
[2016-02-24 09:40:35]  [0.61ms]  UPDATE `test_table` SET `is_active` = 'true', `charged_for_other_money` = '0', `exchanged_for_othertimes` = '0', `avatar_url` = '5', `purchased_gem` = '0', `max_currency` = '100', `signature` = '', `exchanged_for_other_currency` = '0', `gem` = '0', `nick_name` = 'jian zhao', `charged_money` = '0', `purchased_for_othertimes` = '0', `created_at` = '2016-02-24T09:40:35+08:00', `purchased_times` = '0', `charged_for_othertimes` = '0', `exchanged_times` = '0', `exchanged_currency` = '0', `max_gem` = '0', `contact` = '', `gender` = '0', `privilege_level` = '0', `privilege_end_time` = '1984-08-07T07:45:00+08:00', `charged_times` = '0', `purchased_for_other_gem` = '0', `currency` = '100', `bank_currency` = '0', `taked_currency` = '0'  WHERE (`player_id` = '1024')
========================The time save take:42.139479ms

[cristian-sima]

+1

[zj8487]

@jinzhu
Is there any idea on the issue. i test on 1.0 branch. it still exists!

[nbgo]

I have the same problem. Go 1.6, Gorm 1.0, Windows 10 x64.

[jinzhu]

I am keep researching this, not like a quick job, seems like our application on linux server are fine.

[gglluukk]

@zj8487 @cristian-sima

Had same problem with second SQL query (SELECT after INSERT). Cured by the following:

gorm.DefaultCallback.Create().Remove("gorm:force_reload_after_create")

[zj8487]

@jinzhu Is there any progress? I print the details to help finding the issues.
it says the time of sql is very quick, but the total time for insert and update is really slow!

[anan-cn]

problem is db.LogMode(true),

func (s *DB) print(v ...interface{}) {
s.logger.Print(v...)
}
cost too much time @jinzhu @zj8487 ,db.LogMode should be set false in produciton mode

[ericanthonywu]

so? should we use raw query instead of gorm?

[jinzhu]

https://github.com/go-gorm/gorm/issues/3055