Explicit malloc() and free() overhead for C strings

[prashanthpai]

Continuing discussion from pull request https://github.com/kshlm/gogfapi/pull/5

Was doing a ltrace of gogfapi client (Swift's object server) and noticed this performance overhead:

[root@hummingbird ~]# curl -v -X PUT http://localhost:8080/v1/AUTH_test/c1/o4 -d'hello'
[root@hummingbird gfapi]# ltrace -T -ff -p 28906

[pid 28908] malloc(17, 0xc820000f00, 0xc82004afa8, 0xc82004aff8)                                                                                   = 0x7f28f80008c0 <0.021299>
[pid 28908] __errno_location(0xc82004b080, 0xc820000f00, 0xc82004aff0, 0xc82004b080)                                                               = 0x7f291ce45640 <0.006508>
[pid 28908] glfs_stat(0x1ad2550, 0x7f28f80008c0, 0xc82017bd40, 0xc82004b080)                                                                       = 0xffffffff <0.015113>
[pid 28908] free(0x7f28f80008c0, 0xc820000f00, 0xc82004b018, 0xc82004b080)                                                                         = 0 <0.003132>
[pid 28908] malloc(14, 0xc820000f00, 0xc82004aee0, 0xc82004af30)                                                                                   = 0x7f28f80008c0 <0.002026>
[pid 28908] __errno_location(0xc82004afb8, 0xc820000f00, 0xc82004af28, 0xc82004afb8)                                                               = 0x7f291ce45640 <0.002569>
[pid 28908] glfs_stat(0x1ad2550, 0x7f28f80008c0, 0xc82017bdd0, 0xc82004afb8)                                                                       = 0 <0.003362>
[pid 28908] free(0x7f28f80008c0, 0xc820000f00, 0xc82004af50, 0xc82004afb8)                                                                         = 0 <0.001869>
[pid 28908] malloc(51, 0xc820000f00, 0xc82004af80, 0xc82004afd0)                                                                                   = 0x7f28f8002170 <0.001659>
[pid 28908] __errno_location(0xc82004b058, 0xc820000f00, 0xc82004afc0, 0xc82004b058)                                                               = 0x7f291ce45640 <0.001534>
[pid 28908] glfs_creat(0x1ad2550, 0x7f28f8002170, 193, 438)                                                                                        = 0x7f28f80019e0 <0.042730>
[pid 28908] free(0x7f28f8002170, 0xc820000f00, 0xc82004aff0, 0xc82004b058)                                                                         = 0 <0.002435>
[pid 28908] __errno_location(0xc82004af50, 0xc820000f00, 0xc82004aeb0, 0xc82004af50)                                                               = 0x7f291ce45640 <0.020759>
[pid 28908] glfs_write(0x7f28f80019e0, 0xc820140000, 5, 0)                                                                                         = 5 <0.003916>
[pid 28908] malloc(20, 0xc820000f00, 0xc82004aee8, 0xc82004af38)                                                                                   = 0x7f28f8003160 <0.002540>
[pid 28908] __errno_location(0xc82004afc0, 0xc820000f00, 0xc82004af20, 0xc82004afc0)                                                               = 0x7f291ce45640 <0.001196>
[pid 28908] glfs_fsetxattr(0x7f28f80019e0, 0x7f28f8003160, 0xc8200872c0, 168)                                                                      = 0 <0.020598>
[pid 28908] free(0x7f28f8003160, 0xc820000f00, 0xc82004af58, 0xc82004afc0)                                                                         = 0 <0.002918>
[pid 28908] __errno_location(0xc82004b150, 0xc820000f00, 0xc82004b0c0, 0xc82004b150)                                                               = 0x7f291ce45640 <0.003208>
[pid 28908] glfs_fsync(0x7f28f80019e0, 0xc820000f00, 0xc82004b0c0, 0xc82004b150)                                                                   = 0 <0.002416>
[pid 28908] __errno_location(0xc82004b160, 0xc820000f00, 0xc82004b0d0, 0xc82004b160)                                                               = 0x7f291ce45640 <0.001559>
[pid 28908] glfs_close(0x7f28f80019e0, 0xc820000f00, 0xc82004b0d0, 0xc82004b160)                                                                   = 0 <0.002229>
[pid 28908] malloc(51, 0xc820000f00, 0xc82004b068, 0xc82004b0b8)                                                                                   = 0x7f28f8004010 <0.001169>
[pid 28908] malloc(17, 0xc820000f00, 0xc82004b068, 0xc82004b0b8)                                                                                   = 0x7f28f80008c0 <0.000957>
[pid 28908] __errno_location(0xc82004b140, 0xc820000f00, 0xc82004b0b0, 0xc82004b140)                                                               = 0x7f291ce45640 <0.000980>
[pid 28908] glfs_rename(0x1ad2550, 0x7f28f8004010, 0x7f28f80008c0, 0xc82004b140)                                                                   = 0 <0.081158>
[pid 28908] free(0x7f28f80008c0, 0xc820000f00, 0xc82004b0d8, 0xc82004b140)                                                                         = 0 <0.002223>
[pid 28908] free(0x7f28f8004010, 0xc820000f00, 0xc82004b0d8, 0xc82004b140)                                                                         = 0 <0.003288>

For one object PUT

[root@hummingbird gfapi]# ltrace -c -T -ff -p 28906



 time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 67.42    0.104526      104526         1 glfs_rename
  6.98    0.010820       10820         1 glfs_fsync
  5.34    0.008280         690        12 free
  4.99    0.007734         644        12 malloc
  4.91    0.007614         692        11 __errno_location
  3.18    0.004934        1644         3 glfs_getxattr
  3.12    0.004835        4835         1 glfs_creat
  1.47    0.002275        2275         1 glfs_fsetxattr
  1.25    0.001935         967         2 glfs_stat
  0.83    0.001281        1281         1 glfs_close
  0.52    0.000805         805         1 glfs_write
------ ----------- ----------- --------- --------------------
100.00    0.155039                    46 total

For a hundred object PUTs

[root@hummingbird gfapi]# ltrace -c -ff -p 28906

^C% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 43.27    5.952481       59524       100 glfs_rename
 21.39    2.942866       29428       100 glfs_fsync
  7.35    1.011715       10117       100 glfs_fsetxattr
  7.26    0.999125        9991       100 glfs_creat
  5.04    0.692812        1154       600 free
  4.95    0.681092         851       800 __errno_location
  4.67    0.641790        3208       200 glfs_stat
  3.96    0.545340         908       600 malloc
  1.26    0.173293        1732       100 glfs_close
  0.84    0.115284        1152       100 glfs_write
------ ----------- ----------- --------- --------------------
100.00   13.755798                  2800 total