The branch, master has been updated via 87b7a7d script/autobuild.py: build the samba target with --with-profiling-data via b9f9869 s3:smbprofile: profile the system and user space cpu time via 74a16a1 s3:smbprofile: Replace sysv shmem with tdb via 5fa692b s3:smbprofile: specify SMBPROFILE_STATS_SECTION_START() with name vs. display[name] from 7004ccc Implement TestCase.assertIsNotNone for python < 2.7.
https://git.samba.org/?p=samba.git;a=shortlog;h=master - Log ----------------------------------------------------------------- commit 87b7a7dbaa28b29dac316b8b6d953c231529e372 Author: Stefan Metzmacher <me...@samba.org> Date: Mon Dec 8 10:30:56 2014 +0100 script/autobuild.py: build the samba target with --with-profiling-data In future we may get also runtime tests for profiling... Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Michael Adam <ob...@samba.org> Autobuild-User(master): Michael Adam <ob...@samba.org> Autobuild-Date(master): Mon Dec 15 16:20:14 CET 2014 on sn-devel-104 (cherry picked from commit 4958fcdfa30fd9d8dc51ceafaab35721e61e72c7) commit b9f9869d1bec7cff6682d3cda774dcbb2464223b Author: Stefan Metzmacher <me...@samba.org> Date: Fri Nov 14 12:52:33 2014 +0100 s3:smbprofile: profile the system and user space cpu time Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Ralph Boehme <s...@samba.org> commit 74a16a1094278d2c5c8ac800a4f7ed4553d7ac85 Author: Volker Lendecke <v...@samba.org> Date: Mon Sep 29 16:08:17 2014 +0000 s3:smbprofile: Replace sysv shmem with tdb What? This patch gets rid of the central shared memory segment referenced by "profile_p". Instead, every smbd gets a static profile_area where it collects profiling data. Once a second, every smbd writes this profiling data into a record of its own in a "smbprofile.tdb". smbstatus -P does a tdb_traverse on this database and sums up what it finds. Why? At least in my perception sysv IPC has not the best reputation on earth. The code before this patch uses shmat(). Samba ages ago has developed a good abstraction of shared memory: It's called tdb. The main reason why I started this is that I have a request to become more flexible with profiling data. Samba should be able to collect data per share or per user, something which is almost impossible to do with a fixed structure. My idea is to for example install a profile area per share and every second marshall this into one tdb record indexed by share name. smbstatus -P would then also collect the data and either aggregate them or put them into individual per-share statistics. This flexibility in the data model is not really possible with one fixed structure. But isn't it slow? Well, I don't think so. I can't really prove it, but I do believe that on large boxes atomically incrementing a shared memory value for every SMB does show up due to NUMA effects. With this patch the hot code path is completely process-local. Once a second every smbd writes into a central tdb, this of course does atomic operations. But it's once a second, not on every SMB2 read. There's two places where I would like to improve things: With the current code all smbds wake up once a second. With 10,000 potentially idle smbds this will become noticable. That's why the current only starts the timer when something has changed. The second place is the tdb traverse: Right now traverse is blocking in the sense that when it has to switch hash chains it will block. With mutexes, this means a syscall. I have a traverse light in mind that works as follows: It assumes a locked hash chain and then walks the complete chain in one run without unlocking in between. This way the caller can do nonblocking locks in the first round and only do blocking locks in a second round. Also, a lot of syscall overhead will vanish. This way smbstatus -P will have almost zero impact on normal operations. Pair-Programmed-With: Stefan Metzmacher <me...@samba.org> Signed-off-by: Volker Lendecke <v...@samba.org> Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Ralph Boehme <s...@samba.org> commit 5fa692b4aa36f66a14ae9b1512f881ecef23dca3 Author: Stefan Metzmacher <me...@samba.org> Date: Fri Nov 28 09:33:13 2014 +0100 s3:smbprofile: specify SMBPROFILE_STATS_SECTION_START() with name vs. display[name] Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Volker Lendecke <v...@samba.org> Reviewed-by: Ralph Boehme <s...@samba.org> ----------------------------------------------------------------------- Summary of changes: script/autobuild.py | 2 +- source3/include/smbprofile.h | 138 +++++++++++--- source3/profile/profile.c | 401 +++++++++++++++++++++++++++++++++-------- source3/smbd/process.c | 25 +++ source3/smbd/server.c | 2 + source3/smbd/server_exit.c | 2 + source3/smbd/smb2_server.c | 4 +- source3/utils/status_profile.c | 30 +-- source3/wscript | 1 + 9 files changed, 483 insertions(+), 122 deletions(-) Changeset truncated at 500 lines: diff --git a/script/autobuild.py b/script/autobuild.py index 55e4449..6fcdcd4 100755 --- a/script/autobuild.py +++ b/script/autobuild.py @@ -44,7 +44,7 @@ tasks = { ("clean", "make clean", "text/plain") ], # We have 'test' before 'install' because, 'test' should work without 'install' - "samba" : [ ("configure", "./configure.developer --picky-developer ${PREFIX} --with-selftest-prefix=./bin/ab", "text/plain"), + "samba" : [ ("configure", "./configure.developer --picky-developer ${PREFIX} --with-selftest-prefix=./bin/ab --with-profiling-data", "text/plain"), ("make", "make -j", "text/plain"), ("test", "make test FAIL_IMMEDIATELY=1", "text/plain"), ("install", "make install", "text/plain"), diff --git a/source3/include/smbprofile.h b/source3/include/smbprofile.h index ea24165..76d9d2b 100644 --- a/source3/include/smbprofile.h +++ b/source3/include/smbprofile.h @@ -21,15 +21,19 @@ */ +struct tevent_context; + #ifdef WITH_PROFILE #define SMBPROFILE_STATS_ALL_SECTIONS \ SMBPROFILE_STATS_START \ \ - SMBPROFILE_STATS_SECTION_START("SMBD loop") \ + SMBPROFILE_STATS_SECTION_START(global, "SMBD loop") \ SMBPROFILE_STATS_COUNT(connect) \ SMBPROFILE_STATS_COUNT(disconnect) \ SMBPROFILE_STATS_BASIC(idle) \ + SMBPROFILE_STATS_TIME(cpu_user) \ + SMBPROFILE_STATS_TIME(cpu_system) \ SMBPROFILE_STATS_COUNT(request) \ SMBPROFILE_STATS_BASIC(push_sec_ctx) \ SMBPROFILE_STATS_BASIC(set_sec_ctx) \ @@ -37,7 +41,7 @@ SMBPROFILE_STATS_BASIC(pop_sec_ctx) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("System Calls") \ + SMBPROFILE_STATS_SECTION_START(syscall, "System Calls") \ SMBPROFILE_STATS_BASIC(syscall_opendir) \ SMBPROFILE_STATS_BASIC(syscall_fdopendir) \ SMBPROFILE_STATS_BASIC(syscall_readdir) \ @@ -96,7 +100,7 @@ SMBPROFILE_STATS_BASIC(syscall_brl_cancel) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("ACL Calls") \ + SMBPROFILE_STATS_SECTION_START(acl, "ACL Calls") \ SMBPROFILE_STATS_BASIC(get_nt_acl) \ SMBPROFILE_STATS_BASIC(fget_nt_acl) \ SMBPROFILE_STATS_BASIC(fset_nt_acl) \ @@ -104,13 +108,13 @@ SMBPROFILE_STATS_BASIC(fchmod_acl) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("Stat Cache") \ + SMBPROFILE_STATS_SECTION_START(statcache, "Stat Cache") \ SMBPROFILE_STATS_COUNT(statcache_lookups) \ SMBPROFILE_STATS_COUNT(statcache_misses) \ SMBPROFILE_STATS_COUNT(statcache_hits) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("Write Cache") \ + SMBPROFILE_STATS_SECTION_START(writecache, "Write Cache") \ SMBPROFILE_STATS_COUNT(writecache_allocations) \ SMBPROFILE_STATS_COUNT(writecache_deallocations) \ SMBPROFILE_STATS_COUNT(writecache_cached_reads) \ @@ -131,7 +135,7 @@ SMBPROFILE_STATS_COUNT(writecache_flush_reason_sizechange) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("SMB Calls") \ + SMBPROFILE_STATS_SECTION_START(SMB, "SMB Calls") \ SMBPROFILE_STATS_BASIC(SMBmkdir) \ SMBPROFILE_STATS_BASIC(SMBrmdir) \ SMBPROFILE_STATS_BASIC(SMBopen) \ @@ -209,7 +213,7 @@ SMBPROFILE_STATS_BASIC(SMBinvalid) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("Trans2 Calls") \ + SMBPROFILE_STATS_SECTION_START(Trans2, "Trans2 Calls") \ SMBPROFILE_STATS_BASIC(Trans2_open) \ SMBPROFILE_STATS_BASIC(Trans2_findfirst) \ SMBPROFILE_STATS_BASIC(Trans2_findnext) \ @@ -229,7 +233,7 @@ SMBPROFILE_STATS_BASIC(Trans2_report_dfs_inconsistancy) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("NT Transact Calls") \ + SMBPROFILE_STATS_SECTION_START(NT_transact, "NT Transact Calls") \ SMBPROFILE_STATS_BASIC(NT_transact_create) \ SMBPROFILE_STATS_BASIC(NT_transact_ioctl) \ SMBPROFILE_STATS_BASIC(NT_transact_set_security_desc) \ @@ -240,7 +244,7 @@ SMBPROFILE_STATS_BASIC(NT_transact_set_user_quota) \ SMBPROFILE_STATS_SECTION_END \ \ - SMBPROFILE_STATS_SECTION_START("SMB2 Calls") \ + SMBPROFILE_STATS_SECTION_START(smb2, "SMB2 Calls") \ SMBPROFILE_STATS_IOBYTES(smb2_negprot) \ SMBPROFILE_STATS_IOBYTES(smb2_sesssetup) \ SMBPROFILE_STATS_IOBYTES(smb2_logoff) \ @@ -322,8 +326,10 @@ struct smbprofile_stats_iobytes_async { }; struct profile_stats { + uint64_t magic; + struct { #define SMBPROFILE_STATS_START -#define SMBPROFILE_STATS_SECTION_START(name) +#define SMBPROFILE_STATS_SECTION_START(name, display) #define SMBPROFILE_STATS_COUNT(name) \ struct smbprofile_stats_count name##_stats; #define SMBPROFILE_STATS_TIME(name) \ @@ -346,11 +352,13 @@ struct profile_stats { #undef SMBPROFILE_STATS_IOBYTES #undef SMBPROFILE_STATS_SECTION_END #undef SMBPROFILE_STATS_END + } values; }; #define _SMBPROFILE_COUNT_INCREMENT(_stats, _area, _v) do { \ - if (do_profile_flag) { \ - (_area)->_stats.count += (_v); \ + if (smbprofile_state.config.do_count) { \ + (_area)->values._stats.count += (_v); \ + smbprofile_dump_schedule(); \ } \ } while(0) #define SMBPROFILE_COUNT_INCREMENT(_name, _area, _v) \ @@ -361,7 +369,7 @@ struct profile_stats { #define _SMBPROFILE_TIME_ASYNC_START(_stats, _area, _async) do { \ (_async) = (struct smbprofile_stats_time_async) {}; \ if (smbprofile_state.config.do_times) { \ - (_async).stats = &((_area)->_stats), \ + (_async).stats = &((_area)->values._stats), \ (_async).start = profile_timestamp(); \ } \ } while(0) @@ -371,6 +379,7 @@ struct profile_stats { if ((_async).start != 0) { \ (_async).stats->time += profile_timestamp() - (_async).start; \ (_async) = (struct smbprofile_stats_basic_async) {}; \ + smbprofile_dump_schedule(); \ } \ } while(0) @@ -378,12 +387,13 @@ struct profile_stats { struct smbprofile_stats_basic_async _async_name; #define _SMBPROFILE_BASIC_ASYNC_START(_stats, _area, _async) do { \ (_async) = (struct smbprofile_stats_basic_async) {}; \ - if (do_profile_flag) { \ - if (do_profile_times) { \ + if (smbprofile_state.config.do_count) { \ + if (smbprofile_state.config.do_times) { \ (_async).start = profile_timestamp(); \ - (_async).stats = &((_area)->_stats); \ + (_async).stats = &((_area)->values._stats); \ } \ - (_area)->_stats.count += 1; \ + (_area)->values._stats.count += 1; \ + smbprofile_dump_schedule(); \ } \ } while(0) #define SMBPROFILE_BASIC_ASYNC_START(_name, _area, _async) \ @@ -392,12 +402,13 @@ struct profile_stats { if ((_async).start != 0) { \ (_async).stats->time += profile_timestamp() - (_async).start; \ (_async) = (struct smbprofile_stats_basic_async) {}; \ + smbprofile_dump_schedule(); \ } \ } while(0) #define _SMBPROFILE_TIMER_ASYNC_START(_stats, _area, _async) do { \ - (_async).stats = &((_area)->_stats); \ - if (do_profile_times) { \ + (_async).stats = &((_area)->values._stats); \ + if (smbprofile_state.config.do_times) { \ (_async).start = profile_timestamp(); \ } \ } while(0) @@ -427,10 +438,11 @@ struct profile_stats { struct smbprofile_stats_bytes_async _async_name; #define _SMBPROFILE_BYTES_ASYNC_START(_stats, _area, _async, _bytes) do { \ (_async) = (struct smbprofile_stats_bytes_async) {}; \ - if (do_profile_flag) { \ + if (smbprofile_state.config.do_count) { \ _SMBPROFILE_TIMER_ASYNC_START(_stats, _area, _async); \ - (_area)->_stats.count += 1; \ - (_area)->_stats.bytes += (_bytes); \ + (_area)->values._stats.count += 1; \ + (_area)->values._stats.bytes += (_bytes); \ + smbprofile_dump_schedule(); \ } \ } while(0) #define SMBPROFILE_BYTES_ASYNC_START(_name, _area, _async, _bytes) \ @@ -443,6 +455,7 @@ struct profile_stats { if ((_async).stats != NULL) { \ _SMBPROFILE_TIMER_ASYNC_END(_async); \ (_async) = (struct smbprofile_stats_bytes_async) {}; \ + smbprofile_dump_schedule(); \ } \ } while(0) @@ -450,10 +463,11 @@ struct profile_stats { struct smbprofile_stats_iobytes_async _async_name; #define _SMBPROFILE_IOBYTES_ASYNC_START(_stats, _area, _async, _inbytes) do { \ (_async) = (struct smbprofile_stats_iobytes_async) {}; \ - if (do_profile_flag) { \ + if (smbprofile_state.config.do_count) { \ _SMBPROFILE_TIMER_ASYNC_START(_stats, _area, _async); \ - (_area)->_stats.count += 1; \ - (_area)->_stats.inbytes += (_inbytes); \ + (_area)->values._stats.count += 1; \ + (_area)->values._stats.inbytes += (_inbytes); \ + smbprofile_dump_schedule(); \ } \ } while(0) #define SMBPROFILE_IOBYTES_ASYNC_START(_name, _area, _async, _inbytes) \ @@ -467,12 +481,62 @@ struct profile_stats { (_async).stats->outbytes += (_outbytes); \ _SMBPROFILE_TIMER_ASYNC_END(_async); \ (_async) = (struct smbprofile_stats_iobytes_async) {}; \ + smbprofile_dump_schedule(); \ } \ } while(0) extern struct profile_stats *profile_p; -extern bool do_profile_flag; -extern bool do_profile_times; + +struct smbprofile_global_state { + struct { + struct tdb_wrap *db; + struct tevent_context *ev; + struct tevent_timer *te; + } internal; + + struct { + bool do_count; + bool do_times; + } config; + + struct { + struct profile_stats global; + } stats; +}; + +extern struct smbprofile_global_state smbprofile_state; + +void smbprofile_dump_schedule_timer(void); +void smbprofile_dump_setup(struct tevent_context *ev); + +static inline void smbprofile_dump_schedule(void) +{ + if (likely(smbprofile_state.internal.te != NULL)) { + return; + } + + if (unlikely(smbprofile_state.internal.ev == NULL)) { + return; + } + + smbprofile_dump_schedule_timer(); +} + +static inline bool smbprofile_dump_pending(void) +{ + if (smbprofile_state.internal.te == NULL) { + return false; + } + + return true; +} + +void smbprofile_dump(void); + +void smbprofile_cleanup(pid_t pid); +void smbprofile_stats_accumulate(struct profile_stats *acc, + const struct profile_stats *add); +void smbprofile_collect(struct profile_stats *stats); static inline uint64_t profile_timestamp(void) { @@ -531,6 +595,26 @@ static inline uint64_t profile_timestamp(void) #define END_PROFILE(x) #define END_PROFILE_BYTES(x) +static inline bool smbprofile_dump_pending(void) +{ + return false; +} + +static inline void smbprofile_dump_setup(struct tevent_context *ev) +{ + return; +} + +static inline void smbprofile_dump(void) +{ + return; +} + +static inline void smbprofile_cleanup(pid_t pid) +{ + return; +} + #endif /* WITH_PROFILE */ /* The following definitions come from profile/profile.c */ diff --git a/source3/profile/profile.c b/source3/profile/profile.c index c720638..67b1fc7 100644 --- a/source3/profile/profile.c +++ b/source3/profile/profile.c @@ -22,56 +22,49 @@ #include "includes.h" #include "system/shmem.h" #include "system/filesys.h" +#include "system/time.h" #include "messages.h" #include "smbprofile.h" +#include "lib/tdb_wrap/tdb_wrap.h" +#include <tevent.h> +#include "../lib/crypto/crypto.h" -#define PROF_SHMEM_KEY ((key_t)0x07021999) -#define PROF_SHM_MAGIC 0x6349985 -#define PROF_SHM_VERSION 15 +#ifdef HAVE_SYS_RESOURCE_H +#include <sys/resource.h> +#endif -#define IPC_PERMS ((S_IRUSR | S_IWUSR) | S_IRGRP | S_IROTH) - -static int shm_id; -static bool read_only; - -struct profile_header { - int prof_shm_magic; - int prof_shm_version; - struct profile_stats stats; -}; - -static struct profile_header *profile_h; struct profile_stats *profile_p; - -bool do_profile_flag = False; -bool do_profile_times = False; +struct smbprofile_global_state smbprofile_state; /**************************************************************************** Set a profiling level. ****************************************************************************/ void set_profile_level(int level, struct server_id src) { + SMB_ASSERT(smbprofile_state.internal.db != NULL); + switch (level) { case 0: /* turn off profiling */ - do_profile_flag = False; - do_profile_times = False; + smbprofile_state.config.do_count = false; + smbprofile_state.config.do_times = false; DEBUG(1,("INFO: Profiling turned OFF from pid %d\n", (int)procid_to_pid(&src))); break; case 1: /* turn on counter profiling only */ - do_profile_flag = True; - do_profile_times = False; + smbprofile_state.config.do_count = true; + smbprofile_state.config.do_times = false; DEBUG(1,("INFO: Profiling counts turned ON from pid %d\n", (int)procid_to_pid(&src))); break; case 2: /* turn on complete profiling */ - do_profile_flag = True; - do_profile_times = True; + smbprofile_state.config.do_count = true; + smbprofile_state.config.do_times = true; DEBUG(1,("INFO: Full profiling turned ON from pid %d\n", (int)procid_to_pid(&src))); break; case 3: /* reset profile values */ - memset((char *)profile_p, 0, sizeof(*profile_p)); + ZERO_STRUCT(profile_p->values); + tdb_wipe_all(smbprofile_state.internal.db->tdb); DEBUG(1,("INFO: Profiling values cleared from pid %d\n", (int)procid_to_pid(&src))); break; @@ -109,7 +102,13 @@ static void reqprofile_message(struct messaging_context *msg_ctx, { int level; - level = 1 + (do_profile_flag?2:0) + (do_profile_times?4:0); + level = 1; + if (smbprofile_state.config.do_count) { + level += 2; + } + if (smbprofile_state.config.do_times) { + level += 4; + } DEBUG(1,("INFO: Received REQ_PROFILELEVEL message from PID %u\n", (unsigned int)procid_to_pid(&src))); @@ -122,75 +121,319 @@ static void reqprofile_message(struct messaging_context *msg_ctx, ******************************************************************/ bool profile_setup(struct messaging_context *msg_ctx, bool rdonly) { - struct shmid_ds shm_ds; + unsigned char tmp[16] = {}; + MD5_CTX md5; + char *db_name; - read_only = rdonly; + if (smbprofile_state.internal.db != NULL) { + return true; + } - again: - /* try to use an existing key */ - shm_id = shmget(PROF_SHMEM_KEY, 0, 0); + db_name = cache_path("smbprofile.tdb"); + if (db_name == NULL) { + return false; + } - /* if that failed then create one. There is a race condition here - if we are running from inetd. Bad luck. */ - if (shm_id == -1) { - if (read_only) return False; - shm_id = shmget(PROF_SHMEM_KEY, sizeof(*profile_h), - IPC_CREAT | IPC_EXCL | IPC_PERMS); + smbprofile_state.internal.db = tdb_wrap_open( + NULL, db_name, 0, + rdonly ? 0 : TDB_CLEAR_IF_FIRST|TDB_MUTEX_LOCKING, + O_CREAT | (rdonly ? O_RDONLY : O_RDWR), 0644); + if (smbprofile_state.internal.db == NULL) { + return false; } - if (shm_id == -1) { - DEBUG(0,("Can't create or use IPC area. Error was %s\n", - strerror(errno))); - return False; + if (msg_ctx != NULL) { + messaging_register(msg_ctx, NULL, MSG_PROFILE, + profile_message); + messaging_register(msg_ctx, NULL, MSG_REQ_PROFILELEVEL, + reqprofile_message); } - profile_h = (struct profile_header *)shmat(shm_id, 0, - read_only?SHM_RDONLY:0); - if ((long)profile_h == -1) { - DEBUG(0,("Can't attach to IPC area. Error was %s\n", - strerror(errno))); - return False; + MD5Init(&md5); + + MD5Update(&md5, + (const uint8_t *)&smbprofile_state.stats.global, + sizeof(smbprofile_state.stats.global)); + +#define __UPDATE(str) do { \ + MD5Update(&md5, (const uint8_t *)str, strlen(str)); \ +} while(0) +#define SMBPROFILE_STATS_START +#define SMBPROFILE_STATS_SECTION_START(name, display) do { \ + __UPDATE(#name "+" #display); \ +} while(0); +#define SMBPROFILE_STATS_COUNT(name) do { \ + __UPDATE(#name "+count"); \ +} while(0); +#define SMBPROFILE_STATS_TIME(name) do { \ + __UPDATE(#name "+time"); \ +} while(0); +#define SMBPROFILE_STATS_BASIC(name) do { \ + __UPDATE(#name "+count"); \ + __UPDATE(#name "+time"); \ +} while(0); +#define SMBPROFILE_STATS_BYTES(name) do { \ + __UPDATE(#name "+count"); \ + __UPDATE(#name "+time"); \ + __UPDATE(#name "+idle"); \ + __UPDATE(#name "+bytes"); \ +} while(0); +#define SMBPROFILE_STATS_IOBYTES(name) do { \ + __UPDATE(#name "+count"); \ + __UPDATE(#name "+time"); \ + __UPDATE(#name "+idle"); \ + __UPDATE(#name "+inbytes"); \ + __UPDATE(#name "+outbytes"); \ +} while(0); -- Samba Shared Repository