Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add logging of user and sys times for evaluated .tcl #1568

Merged
merged 5 commits into from
May 5, 2024
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
6 changes: 6 additions & 0 deletions eggdrop.conf
Original file line number Diff line number Diff line change
Expand Up @@ -208,6 +208,12 @@ set switch-logfiles-at 300
# date message at midnight, by setting this to 3.
set quiet-save 0

# If log flag d log user and sys times for triggered binds
michaelortmann marked this conversation as resolved.
Show resolved Hide resolved
set log-bind-time 1

# If log flag d log user and sys times for evaluated .tcl commands
set log-tcl-time 1


##### CONSOLE #####

Expand Down
16 changes: 14 additions & 2 deletions src/cmds.c
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
* Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
*/

#include <sys/resource.h>
#include "main.h"
#include "tandem.h"
#include "modules.h"
Expand All @@ -32,7 +33,7 @@ extern struct dcc_t *dcc;
extern struct userrec *userlist;
extern tcl_timer_t *timer, *utimer;
extern int dcc_total, remote_boots, backgrd, make_userfile, conmask, require_p,
must_be_owner;
must_be_owner, log_tcl_time;
extern volatile sig_atomic_t do_restart;
extern unsigned long otraffic_irc, otraffic_irc_today, itraffic_irc,
itraffic_irc_today, otraffic_bn, otraffic_bn_today,
Expand Down Expand Up @@ -2834,6 +2835,8 @@ static void cmd_page(struct userrec *u, int idx, char *par)
*/
static void cmd_tcl(struct userrec *u, int idx, char *msg)
{
struct rusage ru1, ru2;
int r = 0;
int code;
char *result;
Tcl_DString dstr;
Expand All @@ -2842,8 +2845,17 @@ static void cmd_tcl(struct userrec *u, int idx, char *msg)
dprintf(idx, "%s", MISC_NOSUCHCMD);
return;
}
debug1("tcl: evaluate (.tcl): %s", msg);
debug1("tcl: evaluating .tcl %s", msg);
if (log_tcl_time)
r = getrusage(RUSAGE_SELF, &ru1);
code = Tcl_GlobalEval(interp, msg);
if (log_tcl_time && !r && !getrusage(RUSAGE_SELF, &ru2)) {
debug3("tcl: evaluated .tcl %s, user %.3fms sys %.3fms", msg,
(double) (ru2.ru_utime.tv_usec - ru1.ru_utime.tv_usec) / 1000 +
(double) (ru2.ru_utime.tv_sec - ru1.ru_utime.tv_sec ) * 1000,
(double) (ru2.ru_stime.tv_usec - ru1.ru_stime.tv_usec) / 1000 +
(double) (ru2.ru_stime.tv_sec - ru1.ru_stime.tv_sec ) * 1000);
}

/* properly convert string to system encoding. */
Tcl_DStringInit(&dstr);
Expand Down
4 changes: 4 additions & 0 deletions src/tcl.c
Original file line number Diff line number Diff line change
Expand Up @@ -89,6 +89,8 @@ int quiet_reject = 1;
int max_socks = 100;
int par_telnet_flood = 1;
int quiet_save = 0;
int log_bind_time = 1;
int log_tcl_time = 1;
int strtot = 0;
int handlen = HANDLEN;

Expand Down Expand Up @@ -492,6 +494,8 @@ static tcl_ints def_tcl_ints[] = {
{"use-exempts", &use_exempts, 0},
{"use-invites", &use_invites, 0},
{"quiet-save", &quiet_save, 0},
{"log-bind-time", &log_bind_time, 0},
{"log-tcl-time", &log_tcl_time, 0},
{"force-expire", &force_expire, 0},
{"dupwait-timeout", &dupwait_timeout, 0},
{"userfile-perm", &userfile_perm, 0},
Expand Down
7 changes: 4 additions & 3 deletions src/tclhash.c
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@
extern Tcl_Interp *interp;
extern struct dcc_t *dcc;
extern struct userrec *userlist;
extern int dcc_total;
extern int dcc_total, log_bind_time;
extern time_t now;

p_tcl_bind_list bind_table_list;
Expand Down Expand Up @@ -741,11 +741,12 @@ static int trigger_bind(const char *proc, const char *param, char *mask)
strlcpy(last_bind_called, proc, sizeof last_bind_called);
#endif
debug1("triggering bind %s", proc);
r = getrusage(RUSAGE_SELF, &ru1);
if (log_bind_time)
r = getrusage(RUSAGE_SELF, &ru1);
}
x = Tcl_VarEval(interp, proc, param, NULL);
if (proc && proc[0] != '*' && !r) {
if (!getrusage(RUSAGE_SELF, &ru2)) {
if (log_bind_time && !getrusage(RUSAGE_SELF, &ru2)) {
debug3("triggered bind %s, user %.3fms sys %.3fms", proc,
(double) (ru2.ru_utime.tv_usec - ru1.ru_utime.tv_usec) / 1000 +
(double) (ru2.ru_utime.tv_sec - ru1.ru_utime.tv_sec ) * 1000,
Expand Down